Join Log in
Score:1
Ubuntu-one-mw avatar Ubuntu

Kerberized NFS mounts stopped working with Ubuntu 21.10 (still in 22.10)

pn flag
Ubuntu-one-mw

I'm running a Raspberry Pi 400 with Ubuntu. I used to have a working kerberized NFS connection to a Debian based NFS server using Ubuntu 20.04 LTS. Also I'm running another client with 20.04 LTS which still can connect to the NFS server without issues. Since I upgraded the Raspberry PI to 21.10 (then 22.04 and now 22.10) kerberized NFS connections do not work any more. I also thought that it could be due to weak ciphers that are supposed to be removed starting with kernel 5.10. But meanwhile I also deactivated them on my Kerberos Server and re-generated the keys for the Raspberry Pi. It still doesn't work. I've also set up an Ubuntu Server image (22.04 LTS) to check whether I can connect to that one. But this is also not working. So I've proven that the issue is not with my Debian based NFS server (which is quite old, Debian stretch 9.13).

The issue looks like this:

Mount attempt:

sudo mount -t nfs -vvvv -o vers=4.2,sec=krb5i,async,soft vmus01.fritz.box:/srv/nfs4/homes /mnt/vmfs01/srv

returns

mount.nfs: timeout set for Sun Mar  5 12:46:14 2023
mount.nfs: trying text-based options 'vers=4.2,sec=krb5i,soft,addr=192.168.178.48,clientaddr=192.168.178.32'
mount.nfs: mount(2): Invalid argument
mount.nfs: an incorrect mount option was specified

I assume that the issue has to do with the rpc.gssd but I cannot figure out where to find the root cause. In the log I found this information:

Mär 05 12:44:14 pi400 kernel: audit: type=1400 audit(1678016654.181:199): apparmor="ALLOWED" operation="open" class="file" profile="/usr/sbin/sssd" name="/proc/7126/cmdline" pid=958 comm="sssd_nss" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Mär 05 12:44:14 pi400 sudo[7126]: administrator : TTY=pts/3 ; PWD=/tmp ; USER=root ; COMMAND=/usr/bin/mount -t nfs -vvvv -o vers=4.2,sec=krb5i,async,soft vmus01.fritz.box:/srv/nfs4/homes /mnt/vmfs01/srv
Mär 05 12:44:14 pi400 sudo[7126]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mär 05 12:44:14 pi400 kernel: NFS:   parsing nfs mount option 'source'
Mär 05 12:44:14 pi400 kernel: NFS:   parsing nfs mount option 'vers'
Mär 05 12:44:14 pi400 kernel: NFS:   parsing nfs mount option 'sec'
Mär 05 12:44:14 pi400 kernel: NFS: parsing sec=krb5i option
Mär 05 12:44:14 pi400 kernel: NFS:   parsing nfs mount option 'soft'
Mär 05 12:44:14 pi400 kernel: NFS:   parsing nfs mount option 'addr'
Mär 05 12:44:14 pi400 kernel: NFS:   parsing nfs mount option 'clientaddr'
Mär 05 12:44:14 pi400 kernel: NFS: MNTPATH: '/srv/nfs4/homes'
Mär 05 12:44:14 pi400 kernel: --> nfs4_try_get_tree()
Mär 05 12:44:14 pi400 kernel: RPC:       set up xprt to 192.168.178.48 (port 2049) via tcp
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt5c) ev->mask (0x40000100)
Mär 05 12:44:14 pi400 kernel: RPC:       Couldn't create auth handle (flavor 390004)
Mär 05 12:44:14 pi400 kernel: RPC:        destroy backchannel transport
Mär 05 12:44:14 pi400 kernel: RPC:        backchannel list empty= true
Mär 05 12:44:14 pi400 kernel: RPC:       xs_destroy xprt 00000000c38fab83
Mär 05 12:44:14 pi400 kernel: RPC:       xs_close xprt 00000000c38fab83
Mär 05 12:44:14 pi400 kernel: nfs_create_rpc_client: cannot create RPC client. Error = -22
Mär 05 12:44:14 pi400 kernel: RPC:       set up xprt to 192.168.178.48 (port 2049) via tcp
Mär 05 12:44:14 pi400 kernel: RPC:       xs_connect scheduled xprt 0000000038cff69a
Mär 05 12:44:14 pi400 kernel: RPC:       xs_bind 0.0.0.0:902: ok (0)
Mär 05 12:44:14 pi400 kernel: RPC:       worker connecting xprt 0000000038cff69a via tcp to 192.168.178.48 (port 2049)
Mär 05 12:44:14 pi400 kernel: RPC:       0000000038cff69a connect status 115 connected 0 sock state 2
Mär 05 12:44:14 pi400 kernel: RPC:       xs_tcp_state_change client 0000000038cff69a...
Mär 05 12:44:14 pi400 kernel: RPC:       state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
Mär 05 12:44:14 pi400 kernel: RPC:       xs_tcp_send_request(40) = 0
Mär 05 12:44:14 pi400 kernel: RPC:       xs_data_ready...
Mär 05 12:44:14 pi400 kernel: RPC:       setup backchannel transport
Mär 05 12:44:14 pi400 kernel: RPC:       adding req= 00000000499993bf
Mär 05 12:44:14 pi400 kernel: RPC:       setup backchannel transport done
Mär 05 12:44:14 pi400 kernel: svc: initialising pool 0 for NFSv4 callback
Mär 05 12:44:14 pi400 kernel: nfs_callback_create_svc: service created
Mär 05 12:44:14 pi400 kernel: NFS: create per-net callback data; net=f0000000
Mär 05 12:44:14 pi400 kernel: nfs_callback_up: service started
Mär 05 12:44:14 pi400 kernel: NFS: nfs4_discover_server_trunking: testing 'vmus01.fritz.box'
Mär 05 12:44:14 pi400 kernel: RPC:       xs_tcp_send_request(244) = 0
Mär 05 12:44:14 pi400 kernel: RPC:       xs_data_ready...
Mär 05 12:44:14 pi400 kernel: RPC:       xs_tcp_send_request(244) = 0
Mär 05 12:44:14 pi400 kernel: RPC:       xs_data_ready...
Mär 05 12:44:14 pi400 kernel: --> nfs4_proc_create_session clp=00000000651ffdf2 session=00000000ca6dcaff
Mär 05 12:44:14 pi400 kernel: nfs4_init_channel_attrs: Fore Channel : max_rqst_sz=1049620 max_resp_sz=1049480 max_ops=8 max_reqs=64
Mär 05 12:44:14 pi400 kernel: nfs4_init_channel_attrs: Back Channel : max_rqst_sz=4096 max_resp_sz=4096 max_resp_sz_cached=0 max_ops=2 max_reqs=16
Mär 05 12:44:14 pi400 kernel: RPC:       xs_tcp_send_request(196) = 0
Mär 05 12:44:14 pi400 kernel: RPC:       xs_data_ready...
Mär 05 12:44:14 pi400 kernel: --> nfs4_setup_session_slot_tables
Mär 05 12:44:14 pi400 kernel: --> nfs4_realloc_slot_table: max_reqs=30, tbl->max_slots 0
Mär 05 12:44:14 pi400 kernel: nfs4_realloc_slot_table: tbl=00000000ee80cb51 slots=000000007ba616d7 max_slots=30
Mär 05 12:44:14 pi400 kernel: <-- nfs4_realloc_slot_table: return 0
Mär 05 12:44:14 pi400 kernel: --> nfs4_realloc_slot_table: max_reqs=16, tbl->max_slots 0
Mär 05 12:44:14 pi400 kernel: nfs4_realloc_slot_table: tbl=00000000864b6a6c slots=000000005f4f194c max_slots=16
Mär 05 12:44:14 pi400 kernel: <-- nfs4_realloc_slot_table: return 0
Mär 05 12:44:14 pi400 kernel: slot table setup returned 0
Mär 05 12:44:14 pi400 kernel: nfs4_proc_create_session client>seqid 2 sessionid 1678011050:3914836531:203:0
Mär 05 12:44:14 pi400 kernel: nfs4_schedule_state_renewal: requeueing work. Lease period = 5
Mär 05 12:44:14 pi400 kernel: NFS: nfs4_discover_server_trunking: status = 0
Mär 05 12:44:14 pi400 kernel: --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
Mär 05 12:44:14 pi400 kernel: <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mär 05 12:44:14 pi400 kernel: encode_sequence: sessionid=1678011050:3914836531:203:0 seqid=1 slotid=0 max_slotid=0 cache_this=0
Mär 05 12:44:14 pi400 kernel: RPC:       xs_tcp_send_request(124) = 0
Mär 05 12:44:14 pi400 rpc.gssd[7119]: creating client nfs/clnt5c
Mär 05 12:44:14 pi400 rpc.gssd[7119]: scanning client nfs/clnt5c
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for clntdir (nfs/clnt5c) - ev->wd (11) ev->name (info) ev->mask (0x00000200)
Mär 05 12:44:14 pi400 kernel: RPC:       Couldn't create auth handle (flavor 390004)
Mär 05 12:44:14 pi400 kernel: nfs_init_server_rpcclient: couldn't create rpc_client!
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for clntdir (nfs/clnt5c) - ev->wd (11) ev->name (<?>) ev->mask (0x00008000)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: destroying client nfs/clnt5c
Mär 05 12:44:14 pi400 rpc.gssd[7119]: freeing client nfs/clnt5c
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt5d) ev->mask (0x40000100)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: creating client nfs/clnt5d
Mär 05 12:44:14 pi400 rpc.gssd[7119]: scanning client nfs/clnt5d
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for clntdir (nfs/clnt5d) - ev->wd (12) ev->name (info) ev->mask (0x00000100)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: scanning client nfs/clnt5d
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for clntdir (nfs/clnt5d) - ev->wd (12) ev->name (idmap) ev->mask (0x00000100)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for topdir (nfs) - ev->wd (8) ev->name (clnt5e) ev->mask (0x40000100)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: creating client nfs/clnt5e
Mär 05 12:44:14 pi400 rpc.gssd[7119]: scanning client nfs/clnt5e
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for clntdir (nfs/clnt5e) - ev->wd (13) ev->name (info) ev->mask (0x00000200)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for clntdir (nfs/clnt5e) - ev->wd (13) ev->name (<?>) ev->mask (0x00008000)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: destroying client nfs/clnt5e
Mär 05 12:44:14 pi400 rpc.gssd[7119]: freeing client nfs/clnt5e
Mär 05 12:44:14 pi400 kernel: NFS4: Couldn't follow remote path
Mär 05 12:44:14 pi400 kernel: <-- nfs4_try_get_tree() = -22 [error]
Mär 05 12:44:14 pi400 sudo[7126]: pam_unix(sudo:session): session closed for user root
Mär 05 12:44:14 pi400 kernel: RPC:       xs_data_ready...
Mär 05 12:44:14 pi400 kernel: --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
Mär 05 12:44:14 pi400 kernel: <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
Mär 05 12:44:14 pi400 kernel: nfs4_free_slot: slotid 1 highest_used_slotid 0
Mär 05 12:44:14 pi400 kernel: nfs41_sequence_process: Error 0 free the slot 
Mär 05 12:44:14 pi400 kernel: nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
Mär 05 12:44:14 pi400 kernel: <-- nfs41_proc_reclaim_complete status=0
Mär 05 12:44:14 pi400 kernel: --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=16
Mär 05 12:44:14 pi400 kernel: <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mär 05 12:44:14 pi400 kernel: nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
Mär 05 12:44:14 pi400 kernel: --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
Mär 05 12:44:14 pi400 kernel: <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mär 05 12:44:14 pi400 kernel: nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
Mär 05 12:44:14 pi400 kernel: RPC:       xs_tcp_send_request(100) = 0
Mär 05 12:44:14 pi400 kernel: RPC:       xs_data_ready...
Mär 05 12:44:14 pi400 kernel: nfs4_destroy_session Destroy backchannel for xprt 0000000038cff69a
Mär 05 12:44:14 pi400 kernel: RPC:        destroy backchannel transport
Mär 05 12:44:14 pi400 kernel: RPC:        req=00000000499993bf
Mär 05 12:44:14 pi400 kernel: RPC:        free allocations for req= 00000000499993bf
Mär 05 12:44:14 pi400 kernel: RPC:        backchannel list empty= true
Mär 05 12:44:14 pi400 kernel: RPC:       xs_tcp_send_request(92) = 0
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for clntdir (nfs/clnt5d) - ev->wd (12) ev->name (idmap) ev->mask (0x00000200)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for clntdir (nfs/clnt5d) - ev->wd (12) ev->name (info) ev->mask (0x00000200)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: inotify event for clntdir (nfs/clnt5d) - ev->wd (12) ev->name (<?>) ev->mask (0x00008000)
Mär 05 12:44:14 pi400 rpc.gssd[7119]: destroying client nfs/clnt5d
Mär 05 12:44:14 pi400 kernel: RPC:       xs_data_ready...
Mär 05 12:44:14 pi400 kernel: NFS: destroy per-net callback data; net=f0000000
Mär 05 12:44:14 pi400 kernel: svc: svc_destroy(NFSv4 callback)
Mär 05 12:44:14 pi400 kernel: nfs_callback_down: service destroyed
Mär 05 12:44:14 pi400 kernel: RPC:        destroy backchannel transport
Mär 05 12:44:14 pi400 kernel: RPC:        backchannel list empty= true
Mär 05 12:44:14 pi400 kernel: RPC:       xs_destroy xprt 0000000038cff69a
Mär 05 12:44:14 pi400 kernel: RPC:       xs_close xprt 0000000038cff69a
Mär 05 12:44:14 pi400 kernel: RPC:       xs_tcp_state_change client 0000000038cff69a...
Mär 05 12:44:14 pi400 kernel: RPC:       state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
Mär 05 12:44:14 pi400 rpc.gssd[7119]: freeing client nfs/clnt5d

Mär 05 12:44:36 pi400 rpc.gssd[7119]: watchdog: sleeping 30 secs

I tried to modify settings in nfs.conf but without success. Currently it looks like this:

#
# This is a general configuration for the
# NFS daemons and tools
#
[general]
pipefs-directory=/run/rpc_pipefs
#
[exports]
# rootdir=/export
#
[exportfs]
# debug=0
#
[gssd]
verbosity=9
rpc-verbosity=9
# use-memcache=0
use-machine-creds=1
#use-gss-proxy=1
#avoid-dns=1
# limit-to-legacy-enctypes=1
context-timeout=10
rpc-timeout=10
keytab-file=/etc/krb5.keytab
cred-cache-directory=/tmp
preferred-realm= FRITZ.BOX
# set-home=1
upcall-timeout=30
cancel-timed-out-upcalls=0
#
[lockd]
# port=0
# udp-port=0
#
[exportd]
# debug="all|auth|call|general|parse"
# manage-gids=n
# state-directory-path=/var/lib/nfs
# threads=1
# cache-use-ipaddr=n
# ttl=1800
[mountd]
debug="all|auth|call|general|parse"
manage-gids=y
# descriptors=0
# port=0
# threads=1
reverse-lookup=y
# state-directory-path=/var/lib/nfs
# ha-callout=
# cache-use-ipaddr=n
# ttl=1800
#
[nfsdcld]
debug=9
# storagedir=/var/lib/nfs/nfsdcld
#
[nfsdcltrack]
debug=9
# storagedir=/var/lib/nfs/nfsdcltrack
#
[nfsd]
debug=9
# threads=8
# host=
# port=0
# grace-time=90
# lease-time=90
udp=n
tcp=y
vers3=n
vers4=n
vers4.0=n
vers4.1=n
vers4.2=n
# rdma=n
# rdma-port=20049

[statd]
debug=9
# port=0
# outgoing-port=0
# name=
# state-directory-path=/var/lib/nfs/statd
# ha-callout=
# no-notify=0
#
[sm-notify]
debug=9
# force=0
# retry-time=900
# outgoing-port=
# outgoing-addr=
# lift-grace=y
#
[svcgssd]
# principal=

/etc/krb5.keytab contains the following:

Keytab name: FILE:/etc/krb5.keytab
KVNO Principal
---- ---------------------------------------------
   2 nfs/pi400.fritz.box@FRITZ.BOX (aes256-cts-hmac-sha1-96) 
   2 host/pi400.fritz.box@FRITZ.BOX (aes256-cts-hmac-sha1-96)

Any help on this will be highly appreciated. Thank you very much.

Kind regards Martin

376
1 + 0
nfs
Score:1
Ubuntu-one-mw avatar Ubuntu
pn flag
Ubuntu-one-mw

I found the reason. I checked the kernel modules and found one missing on the Raspberry PI. This is how it looks like on my working Ubuntu Client (Intel I3, Ubuntu 20.04):

lsmod | grep gss

returns

rpcsec_gss_krb5        40960  11
auth_rpcgss            94208  4 rpcsec_gss_krb5
sunrpc                397312  31 nfsv4,auth_rpcgss,lockd,nfsv3,rpcsec_gss_krb5,nfs_acl,nfs

And rpcsec_gss_krb5 is missing on the Raspberry PI. Currently I'm using kernel version 5.19.0-1011-raspi. rpcsec_gss.krb5.ko is missing here! If I look on packages.ubuntu.com it looks like the last version that included the rpcsec module was 5.19.0-1004-raspi. Somehow they put the kernel module into an extra package which has to be installed manually obviously. I just installed linux-modules-extra-5.19.0-1011-raspi and now rpcsec_gss.krb5.ko is available. I loaded it via modprobe. The nfs* kernel modules are also not present, but it turned out that they will be loaded when executing the mount command later on. Trying to mount the NFS server share does not result in

mount.nfs: mount(2): Invalid argument

any more. Now I get

mount.nfs: mount(2): Permission denied

Somehow the contents of /etc/krb5.keytab seemed to be invalid. I deleted it and regenerated it by using

sudo kinit some-kerberos-admin/admin
sudo kadmin -p some-kerberos-admin/admin
ktadd nfs/pi400.fritz.box

Now it is working. To load the kernel module automatically during startup I added rpcsec_gss_krb5 to /etc/modules which is working very nicely now. Finally added the mount command to /etc/fstab and I'm done.

Some more words to how I debugged the issue. Add / uncomment the following entries in /etc/nfs.conf in the gssd section:

[gssd]
verbosity=9
rpc-verbosity=9

(BTW: I commented out again nearly all entries in nfs.conf as it was supplied by the package maintainer). Having done this rpc.gssd will add a lot of output in the syslog. Besides this the following commands helped me because they enable log output from the kernel:

rpcdebug -m rpc -s all    # sets all debug flags for RPC
rpcdebug -m nfs -s all    # sets all debug flags for RPC

To inspect the log output I opened a new console window and monitored the syslog output with

journalctl -f

See also this Webpage from the ARCH Linux team which was really helpful: NFS/Troubleshooting

I filed a bug report on launchpad: Kerberized NFS mounts not working on Raspberry PI

Maybe this information is also useful for somebody else...

Regards Martin

+ 0
ธงชาติไทย
Elon Musk
I sit in a Tesla and translated this thread with Ai:

mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.