Re: Current state of nfsdv4 recovery.

[Matthew Schumacher <schu@schu.net>]

On 3/6/26 12:49 PM, Jeff Layton wrote:
> On Fri, 2026-03-06 at 11:46 -0800, Matthew Schumacher wrote:
<snip>
>>
>> Moving from nodeA to nodeB
>>
>> NodeA: Remove nfsd ip address
>> NodeA: /usr/sbin/exportfs -au
>> NodeA: /usr/sbin/rpc.nfsd 0
>> NodeA: killall --ns $$ -q -v -w rpc.mountd
>> NodeA: killall --ns $$ -q -v -w nfsdcld
>> NodeA: killall --ns $$ -q -v -w rpc.idmapd
>> NodeA: killall --ns $$ -q -v -w rpcbind
>> NodeA: umount /var/lib/nfs/rpc_pipefs
>> NodeA: zpool export (which umounts /var/lib/nfs)
>>
>> NodeB: zpool import (which mounts /var/lib/nfs)
>> NodeB: mount /proc/fs/nfs if not previously mounted
>> NodeB: mount -t rpc_pipefs -o nodev sunrpc /var/lib/nfs/rpc_pipefs
>> NodeB: /sbin/rpcbind -l -w
>> NodeB: /usr/sbin/rpc.idmapd
>> NodeB: /usr/sbin/nfsdcld -d
>> NodeB: /usr/sbin/exportfs -av
>> NodeB: /usr/sbin/rpc.mountd
>> NodeB: /usr/sbin/rpc.nfsd -s -V 4.2 -U -t 8
>> NodeB: start nfsd ip address
>>
>>   From what I understand, nfsdcld writes the lock information to
>> /var/lib/nfs/nfsdcltrack/main.sqlite which is moved to the other side
>> and everything is started, but I still lose locks when I migrate.
>>
>> Mar  6 08:39:14 nfsha user.warn kernel: [37675.787509] NFS:
>> 10.255.255.3: lost 1 locks
>>
>> I think the problem is that kernel (6.12.74) isn't getting the locks
>> reported to it when nfsdcld starts.  Here are some logs:
>>
>> Mar  6 08:38:46 nfsha daemon.warn rpc.idmapd[14113]: Setting log level to 0
>> Mar  6 08:38:46 nfsha daemon.warn rpc.idmapd[14113]: libnfsidmap: Unable
>> to determine the NFSv4 domain; Using 'localdomain' as the NFSv4 domain
>> which means UIDs will be mapped to the 'Nobody-User' user defined in
>> /etc/idmapd.conf
>> Mar  6 08:38:46 nfsha daemon.info nfsdcld[14116]:
>> sqlite_startup_query_grace: current_epoch=2 recovery_epoch=1
>> Mar  6 08:38:46 nfsha daemon.info nfsdcld[14116]:
>> sqlite_check_db_health: returning 0
>> Mar  6 08:38:46 nfsha daemon.info nfsdcld[14116]: attaching
>> /var/lib/nfs/nfsdcltrack/main.sqlite
>> Mar  6 08:38:46 nfsha daemon.notice rpc.mountd[14125]: Version 2.8.5
>> starting
>> Mar  6 08:38:46 nfsha daemon.info nfsdcld[14116]: detaching database
>> Mar  6 08:38:46 nfsha daemon.info nfsdcld[14116]:
>> sqlite_copy_cltrack_records: returning 0
>> Mar  6 08:38:46 nfsha daemon.info nfsdcld[14116]: sqlite_prepare_dbh:
>> num_cltrack_records = 2
>> Mar  6 08:38:47 nfsha user.info kernel: [37649.053531] NFSD: Using UMH
>> upcall client tracking operations.
>> Mar  6 08:38:47 nfsha user.info kernel: [37649.055262] NFSD: Using UMH
>> upcall client tracking operations.
> 
> The kernel failed to recognize the cld upcall for some reason, so it
> fell back to running the usermodehelper upcall.
<snip>

Thanks for the reply, I figured out why /var/lib/nfs/rpc_pipefs/nfsd/cld 
was missing, I had CONFIG_NFSD_LEGACY_CLIENT_TRACKING enabled in the 
kernel.  Now that that is fixed, nfsv4 recovery seems to be working 
because I see it notifying the nfs clients and ending the grace period, 
but I'm still losing the lock.  Any idea why?  Or how to debug?

Mar  6 14:53:31 nfsha daemon.warn rpc.idmapd[3243]: Setting log level to 0
Mar  6 14:53:31 nfsha daemon.warn rpc.idmapd[3243]: libnfsidmap: Unable 
to determine the NFSv4 domain; Using 'localdomain' as the NFSv4 domain 
which means UIDs will be mapped to the 'Nobody-User' user defined in 
/etc/idmapd.conf
Mar  6 14:53:31 nfsha daemon.notice rpc.mountd[3252]: Version 2.8.5 starting
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: 
sqlite_startup_query_grace: current_epoch=5 recovery_epoch=0
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: sqlite_check_db_health: 
returning 0
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: cld_pipe_init: init 
pipe handlers
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: cld_pipe_open: opening 
upcall pipe /var/lib/nfs/rpc_pipefs/nfsd/cld
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: cld_pipe_open: open of 
/var/lib/nfs/rpc_pipefs/nfsd/cld failed: No such file or directory
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: main: Starting event 
dispatch handler.
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: cld_inotify_cb: called 
for EV_READ
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: cld_pipe_open: opening 
upcall pipe /var/lib/nfs/rpc_pipefs/nfsd/cld
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: cld_get_version: 
version = 2.
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: Doing downcall with 
status 0
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: cld_gracestart: 
updating grace epochs
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: sqlite_grace_start: 
current_epoch=6 recovery_epoch=5
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: cld_gracestart: sending 
client records to the kernel
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: Sending client Linux 
NFSv4.2 virttest-2
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: Sending client Linux 
NFSv4.2 virttest-1
Mar  6 14:53:31 nfsha daemon.info nfsdcld[3254]: Doing downcall with 
status 0
Mar  6 14:53:31 nfsha user.info kernel: [ 1831.162648] NFSD: Using 
nfsdcld client tracking operations.
Mar  6 14:53:31 nfsha user.info kernel: [ 1831.162651] NFSD: starting 
90-second grace period (net f0000000)
Mar  6 14:53:31 nfsha daemon.info IPaddr(failover-ip)[3283]: INFO: Using 
calculated netmask for 10.255.255.3: 255.255.255.0
Mar  6 14:53:31 nfsha daemon.info IPaddr(failover-ip)[3283]: INFO: eval 
ifconfig eth3:0 10.255.255.3 netmask 255.255.255.0 broadcast 10.255.255.255
Mar  6 14:53:34 nfsha daemon.notice rpc.mountd[3252]: v4.2 client 
attached: 0x2baa617369ab5aeb from "10.255.255.1:51662"
Mar  6 14:53:34 nfsha daemon.info nfsdcld[3254]: cld_create: create 
client record.
Mar  6 14:53:34 nfsha daemon.info nfsdcld[3254]: 
sqlite_insert_client_and_princhash: returning 0
Mar  6 14:53:34 nfsha daemon.info nfsdcld[3254]: Doing downcall with 
status 0
Mar  6 14:53:42 nfsha daemon.notice rpc.mountd[3252]: v4.2 client 
attached: 0x2baa617469ab5aeb from "10.255.255.2:53976"
Mar  6 14:53:42 nfsha daemon.info nfsdcld[3254]: cld_create: create 
client record.
Mar  6 14:53:42 nfsha daemon.info nfsdcld[3254]: 
sqlite_insert_client_and_princhash: returning 0
Mar  6 14:53:42 nfsha daemon.info nfsdcld[3254]: Doing downcall with 
status 0
Mar  6 14:53:42 nfsha daemon.info nfsdcld[3254]: cld_gracedone: grace done.
Mar  6 14:53:42 nfsha user.info kernel: [ 1842.038046] NFSD: all clients 
done reclaiming, ending NFSv4 grace period (net f0000000)
Mar  6 14:53:42 nfsha daemon.info nfsdcld[3254]: sqlite_grace_done: 
current_epoch=6 recovery_epoch=0
Mar  6 14:53:42 nfsha daemon.info nfsdcld[3254]: Doing downcall with 
status 0
Mar  6 14:53:48 nfsha user.warn kernel: [ 1847.336008] NFS: 
10.255.255.3: lost 1 locks

I'm mounting with:

mount -t nfs -o 
rw,sync,vers=4.2,hard,noresvport,proto=tcp,timeo=600,retrans=2 
10.255.255.3:/dev/datastore-stub /datastore