#880549 nfs-kernel-server: NFSv4 sec=krb5p option broken on stretch

Package:
nfs-kernel-server
Source:
nfs-utils
Description:
support for NFS kernel server
Submitter:
"Roberto C. Sanchez"
Date:
2023-12-18 13:51:03 UTC
Severity:
important
#880549#5
Date:
2017-11-02 04:08:23 UTC
From:
To:
I have recently upgraded my NFS server from Jessie to Stretch.  It was
the last system on my network that needed to be upgraded.  After the
upgrade, I found that NFSv4 was nearly unusable.  All user home
directories, as well as backup and scratch space, are mounted via NFS.
Users trying to log in to a default GNOME session would experience hangs
that appeared to never resolve themselves.  Logging in through ssh
resulted in ~2 minutes delay before a bash prompt would appear.

I attempted several things to troubleshoot the problem, including
reverting to kernel 3.16.0 from Jessie and nfs-utils 1.2.8-9.1.  I tried
going all the way back to nfs-utils 1.2.8-9, but the version of systemd
in Stretch has "nfs-common (<< 1:1.2.8-9.1)".  Even after reverting the
problem persisted.  Based on that, I think that the problem may have
been introduced as far back as 1.2.8-9.1.

The problem also manifested itself in the form of problems for users
logged directly into the NFS server.  Even though file accesses are
local in that scenario, if an NFS client had attemped to access a file
and hung on it, then it would also cause problems on the NFS server.
For example, I have a large MBOX file that I access with mutt.  If I
access the file from an NFS client then it appears to hang with messages
like this flooding syslog on the client:

vmunix: [918369.611122] NFS: nfs4_reclaim_open_state: Lock reclaim failed

Trying to then open that same mbox with mutt on the NFS server causes
mutt to segfault because the call to fcntl() returns an error.

The only thing that resolved the problem was switching my exports from
sec=krb5p to sec=krb5i.  Of course, this is considerably less desirable
than krb5p in some cases.

I believe the that problem is with rpc.svcgssd.  Here is part of what
got captured in syslog during a failure:

Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: libnfsidmap: using domain: example.com
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: libnfsidmap: Realms list: 'EXAMPLE.COM'
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: libnfsidmap: processing 'Method' list
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: libnfsidmap: loaded plugin /lib/x86_64-linux-gnu/libnfsidmap/nsswitch.so for method nsswitch
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: entering poll
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: leaving poll
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: handling null request
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: sname = nfs/ws1.example.com@EXAMPLE.COM
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: doing downcall
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1509615211 (25678 from now), clnt: nfs@ws1.example.com, uid: -1, gid: -1, num aux grps: 0:
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: sending null reply
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: writing message: \x [snip message payload]
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: finished handling null request
Nov  1 22:25:33 nfssrv rpc.svcgssd[30152]: entering poll
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: leaving poll
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: handling null request
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: sname = nfs/ws2.example.com@EXAMPLE.COM
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: doing downcall
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1509603982 (14448 from now), clnt: nfs@ws2.example.com, uid: -1, gid: -1, num aux grps: 0:
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: sending null reply
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: writing message: \x [snip message payload]
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: finished handling null request
Nov  1 22:25:34 nfssrv rpc.svcgssd[30152]: entering poll
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: leaving poll
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: handling null request
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: sname = nfs/ws3.example.com@EXAMPLE.COM
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: doing downcall
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1509603453 (13881 from now), clnt: nfs@ws3.example.com, uid: -1, gid: -1, num aux grps: 0:
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: sending null reply
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: writing message: \x [snip message payload]
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: finished handling null request
Nov  1 22:26:12 nfssrv rpc.svcgssd[30152]: entering poll
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: leaving poll
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: handling null request
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: sname = nfs/ws3.example.com@EXAMPLE.COM
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: doing downcall
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1509603453 (13756 from now), clnt: nfs@ws3.example.com, uid: -1, gid: -1, num aux grps: 0:
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: sending null reply
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: writing message: \x [snip message payload]
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: finished handling null request
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: entering poll
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: leaving poll
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: handling null request
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: sname = nfs/ws3.example.com@EXAMPLE.COM
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: doing downcall
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1509603453 (13756 from now), clnt: nfs@ws3.example.com, uid: -1, gid: -1, num aux grps: 0:
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: sending null reply
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: writing message: \x [snip message payload]
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: finished handling null request
Nov  1 22:28:17 nfssrv rpc.svcgssd[30152]: entering poll
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: leaving poll
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: handling null request
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: sname = nfs/ws2.example.com@EXAMPLE.COM
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: doing downcall
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1509603982 (14280 from now), clnt: nfs@ws2.example.com, uid: -1, gid: -1, num aux grps: 0:
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: sending null reply
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: writing message: \x [snip message payload]
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: finished handling null request
Nov  1 22:28:22 nfssrv rpc.svcgssd[30152]: entering poll
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: leaving poll
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: handling null request
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: sname = roberto@EXAMPLE.COM
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: doing downcall
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1509623547 (33835 from now), clnt: <null>, uid: 3167, gid: 100, num aux grps: 17:
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (   1) 100
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (   2) 4
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (   3) 24
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (   4) 29
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (   5) 33
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (   6) 44
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (   7) 46
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (   8) 50
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (   9) 60
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (  10) 113
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (  11) 115
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (  12) 125
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (  13) 132
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (  14) 500
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (  15) 501
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (  16) 502
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]:   (  17) 503
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: sending null reply
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: writing message: \x [snip message payload]
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: finished handling null request
Nov  1 22:28:32 nfssrv rpc.svcgssd[30152]: entering poll
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: leaving poll
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: handling null request
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: sname = nfs/ws2.example.com@EXAMPLE.COM
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: doing downcall
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1509603982 (14260 from now), clnt: nfs@ws2.example.com, uid: -1, gid: -1, num aux grps: 0:
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: sending null reply
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: writing message: \x [snip message payload]
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: finished handling null request
Nov  1 22:28:42 nfssrv rpc.svcgssd[30152]: entering poll
Nov  1 22:32:42 nfssrv rpc.svcgssd[30152]: exiting on signal 15


- -- Package-specific info:
- -- rpcinfo --
   program vers proto   port  service
    100000    4   tcp    111  portmapper
    100000    3   tcp    111  portmapper
    100000    2   tcp    111  portmapper
    100000    4   udp    111  portmapper
    100000    3   udp    111  portmapper
    100000    2   udp    111  portmapper
    391002    2   tcp    650  sgi_fam
    100005    1   udp  32767  mountd
    100005    1   tcp  32767  mountd
    100005    2   udp  32767  mountd
    100005    2   tcp  32767  mountd
    100005    3   udp  32767  mountd
    100005    3   tcp  32767  mountd
    100003    3   tcp   2049  nfs
    100003    4   tcp   2049  nfs
    100227    3   tcp   2049
    100003    3   udp   2049  nfs
    100003    4   udp   2049  nfs
    100227    3   udp   2049
    100021    1   udp  52460  nlockmgr
    100021    3   udp  52460  nlockmgr
    100021    4   udp  52460  nlockmgr
    100021    1   tcp  37351  nlockmgr
    100021    3   tcp  37351  nlockmgr
    100021    4   tcp  37351  nlockmgr
- -- /etc/default/nfs-kernel-server --
RPCNFSDCOUNT=8
RPCNFSDPRIORITY=0
RPCMOUNTDOPTS="-p 32767"
NEED_SVCGSSD="yes"
RPCSVCGSSDOPTS=""
- -- /etc/exports --
/srv/nfs	192.168.0.0/16(sync,rw,fsid=0,crossmnt,insecure,no_subtree_check,anonuid=65534,anongid=65534,sec=krb5i)
/srv/nfs/home	192.168.0.0/16(sync,rw,insecure,no_subtree_check,anonuid=65534,anongid=65534,sec=krb5i)
/srv/nfs/backup	192.168.0.0/16(sync,rw,insecure,no_subtree_check,anonuid=65534,anongid=65534,sec=krb5i)
/srv/nfs/scratch	192.168.0.0/16(sync,rw,insecure,no_subtree_check,anonuid=65534,anongid=65534,sec=krb5i)

- -- System Information:
Debian Release: 9.2
  APT prefers stable-updates
  APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 4.9.0-4-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_US.utf8, LC_CTYPE=en_US.utf8 (charmap=UTF-8), LANGUAGE=en_US.utf8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages nfs-kernel-server depends on:
ii  init-system-helpers  1.48
ii  keyutils             1.5.9-9
ii  libblkid1            2.29.2-1
ii  libc6                2.24-11+deb9u1
ii  libcap2              1:2.25-1
ii  libsqlite3-0         3.16.2-5
ii  libtirpc1            0.2.5-1.2
ii  libwrap0             7.6.q-26
ii  lsb-base             9.20161125
ii  netbase              5.4
ii  nfs-common           1:1.3.4-2.1
ii  ucf                  3.0036

nfs-kernel-server recommends no packages.

nfs-kernel-server suggests no packages.

- -- no debconf information
-----BEGIN PGP SIGNATURE-----

iQIzBAEBCgAdFiEEz9ERzDttUsU/BH8iLNd4Xt2nsg8FAln6mi4ACgkQLNd4Xt2n
sg+OPRAAksDf+IR6dTn1Gl8OM4IOMVi5S48i+S6n3sDy9Uv04zRX1sdvTuzvGF1d
4mRqPson+eQ3CnuMQIH8XOMZJdrZoB7bsjMWjZC9FgBn42oE7wOxcMJW+FC1qCYe
AJMan4ssGDec62XnBkkZY2byhvbXygEmSq/cCQlCKp3amwe3VEm+lqf1qFKl2euV
qrnkgk7aAgrH6zu+q5WgAyrEZzvDi7NbcGheUe0NitAKEu2zR+Iq6mMOEP9rd91s
sgJ2tCHvwZtE6FoUHk9GJrluZyzItBIGV+aaA9PFjJcoQgxB5mE5cS0vFlfXiVbm
xS9v67UJXp/H7R5S+mnoMDqfKi+TCW+FaLEj5s+4bpYd7sk6Pyqugj3yEj6OYKAw
u2G7iB4MA64roxGeIEghgPvW/Zmuvpa+pi6RjOUcyvO4lyNGMVUM7TP59fWuXbwv
kwQ+coBI6SxAUnKOiA9MADHZcUxjdhPWckkTFagijv9mipAY9+G6+fWBY3iFZrMO
vrGABHecEzV5TzKv4J+sSGl5581/+vImK3SIUA6ILBED1SkWmFFonekE9P0YDgFr
tR2+vcCvhQehYSQW/hifJpbY/3puUXYOvqQmv+Be3AVw6hBaxVfzY1yjkDemjKXr
oHmDZ5L76TokKoiv45JYIWAr8sjNsxScDUlhnP+Ou7Tvi8eUIqM=
=CbNN
-----END PGP SIGNATURE-----
#880549#10
Date:
2019-11-09 09:13:49 UTC
From:
To:
This bug is still present in Buster.

It can be workarounded by using the mount option "vers=4.0".

NFS versions 4.2 (default in Buster), and 4.1 are affected by this bug.
Version 4.0 works fine.  Can anyone confirm this?
#880549#15
Date:
2019-11-09 09:43:09 UTC
From:
To:
This bug is still present in Buster.

It can be workarounded by using the mount option "vers=4.0".

NFS versions 4.2 (default in Buster), and 4.1 are affected by this bug.
Version 4.0 works fine.  Can anyone confirm this?
#880549#18
Date:
2020-02-27 13:50:56 UTC
From:
To:
Hello all,

in the last days we also got problems / outages because of this "NFS:
nfs4_reclaim_open_state: Lock reclaim failed!" bug.
For explanation:

It is a 8 years old cluster, cross-connected two vSphere 6.0 servers and
jessie+stretch+buster VMs.
The fileserver is Debian Jessie with pacemaker active/passive setup. The
active part is on esx-1.
There are two webnodes: node-1 and node-2. node-2 is located on esx-2
(where not the active nfs server part is). node-2 got massive problems,
high load, outages and all we found out is this message (and also stuck
php-fpm processes):
NFS: nfs4_reclaim_open_state: Lock reclaim failed!

fstab looks like:
192.168.55.8:/nfs/cms /srv/nfs/typo3_cms nfs
_netdev,auto,hard,intr,rw,noatime,nodiratime 0 0

Web node-1 didnt got the problem, so we thought it may be a hardware or
configuration problem.

So what changed, that we just get now this error?:
- we are always up to date, so maybe an oldstable update? We dont think
so, node-1 is running fine
- the main change was, that we have upgraded TYPO3 from 8.7.27 up to
9.5.13, and also php-fpm from 7.0 to 7.3
- the whole TYPO3 - except of the typo3-src - is located on the NFS and
delivered about apache

Workaround:
I tried out the "workaround" and mounting the nfs now with:
192.168.55.8:/nfs/cms /srv/nfs/typo3_cms nfs4
vers=4.0,_netdev,auto,hard,intr,rw,noatime,nodiratime 0 0

So the client is using nfs 4.0, not 4.1. It looks fine now.. No outages,
no high load and a clean dmesg.

I think in our setup this bug is triggered by the following conditions:
- TYPO3 9.5.x and PHP 7.3.x is doing something over 8.7.x+7.0.x, which
triggeres the bug...
- ... which is located in the NFS v4.1 code, but not in the 4.0 client code
- it looks like it was also only triggered, if the datastore code left
one esx node. The webnode on the same hardware was not affected
#880549#23
Date:
2023-12-18 13:09:12 UTC
From:
To:
In Bookworm I no longer see the "lock reclaim failed" errors.

Further investigation revealed that the affected installations were also
affected by five-second delays as described here
<https://lore.kernel.org/linux-nfs/59682160-a246-395a-9486-9bbf11686740@mathematik.uni-wuerzburg.de/>.
These show similar symptoms and they also occur on nfs v4.{1,2} only.

So I had to change the lines in <etc/exports> from

| /srv/nfs gss/krb5p(rw,fsid=0,crossmnt,no_subtree_check)

to

| /srv/nfs *(sec=krb5p,rw,fsid=0,crossmnt,no_subtree_check)

Done that and everything runs fine.

In my experience the bug report can be closed.