Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.debian.kernel > #90004 > unrolled thread
| Started by | "Tyler W. Ross" <twr+debbugs@tylerwross.com> |
|---|---|
| First post | 2025-11-12 22:50 +0100 |
| Last post | 2026-03-09 22:10 +0100 |
| Articles | 20 — 6 participants |
Back to article view | Back to linux.debian.kernel
Bug#1120598: nfs-common: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <twr+debbugs@tylerwross.com> - 2025-11-12 22:50 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 Salvatore Bonaccorso <carnil@debian.org> - 2025-11-13 06:10 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-13 18:20 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-13 19:10 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-13 20:00 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-14 05:40 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-14 06:20 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-16 01:50 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 Trond Myklebust <trondmy@kernel.org> - 2025-11-16 19:30 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-17 06:30 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 Scott Mayhew <smayhew@redhat.com> - 2025-11-18 00:10 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 Scott Mayhew <smayhew@redhat.com> - 2025-11-18 00:10 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-18 05:20 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 Scott Mayhew <smayhew@redhat.com> - 2025-11-18 19:00 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-19 00:50 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-17 19:50 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-18 05:40 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 Scott Mayhew <smayhew@redhat.com> - 2025-11-19 14:40 +0100
Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 "Tyler W. Ross" <TWR@tylerwross.com> - 2025-11-19 18:30 +0100
Bug#1120598: marked as done (nfs: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2) "Debian Bug Tracking System" <owner@bugs.debian.org> - 2026-03-09 22:10 +0100
| From | "Tyler W. Ross" <twr+debbugs@tylerwross.com> |
|---|---|
| Date | 2025-11-12 22:50 +0100 |
| Subject | Bug#1120598: nfs-common: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LQqSZ-cvae-3@gated-at.bofh.it> |
Package: nfs-common
Version: 1:2.8.4-1+b1
Severity: important
X-Debbugs-Cc: twr+debbugs@tylerwross.com
When the session key of a kerberos ticket uses a SHA2 cipher (aes256-cts-hmac-sha384-192 and aes128-cts-hmac-sha256-128 tested), readdir requests fail.
SHA1 ciphers (aes256-cts-hmac-sha1-96 and aes128-cts-hmac-sha1-96 tested) work as expected.
ls reports the following:
ls: reading directory '/mnt/example/': Input/output error
stat and touch of files and directories is working, and cat'ing a file works (see also: later note about cat with NFSv4.1 and 4.0).
Example of a non-working ticket, as reported by klist -e:
11/12/25 18:37:30 11/13/25 17:49:03 nfs/nfssrv.ipa.twrlab.net@IPA.TWRLAB.NET
Etype (skey, tkt): aes256-cts-hmac-sha384-192, aes256-cts-hmac-sha384-192
Example of a working ticket:
11/12/25 19:01:46 11/13/25 18:27:33 nfs/nfssrv.ipa.twrlab.net@IPA.TWRLAB.NET
Etype (skey, tkt): aes256-cts-hmac-sha1-96, aes256-cts-hmac-sha384-192
If rpcdebug is enabled for nfs and rpc modules, the following is logged to dmesg:
[332376.797836] NFS: nfs_weak_revalidate: inode 262146 is valid
[332376.798512] NFS: revalidating (0:58/262146)
[332376.799169] --> nfs41_call_sync_prepare data->seq_server 00000000e22b1bd9
[332376.799916] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=64
[332376.800764] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[332376.801507] RPC: gss_krb5_get_mic_v2
[332376.802009] encode_sequence: sessionid=1762048597:1479457708:22:0 seqid=27 slotid=0 max_slotid=0 cache_this=0
[332376.803204] RPC: gss_krb5_get_mic_v2
[332376.803726] RPC: xs_tcp_send_request(260) = 0
[332376.804536] RPC: gss_krb5_verify_mic_v2
[332376.805093] RPC: gss_krb5_verify_mic_v2
[332376.805643] decode_attr_type: type=040000
[332376.806149] decode_attr_change: change attribute=22
[332376.806866] decode_attr_size: file size=4096
[332376.807398] decode_attr_fsid: fsid=(0xfdcb5a40986843e0/0xa4fc6c44ad8345ad)
[332376.808154] decode_attr_fileid: fileid=262146
[332376.808742] decode_attr_fs_locations: fs_locations done, error = 0
[332376.809495] decode_attr_mode: file mode=0777
[332376.810042] decode_attr_nlink: nlink=3
[332376.810695] decode_attr_owner: uid=591200000
[332376.811229] decode_attr_group: gid=591200004
[332376.811761] decode_attr_rdev: rdev=(0x0:0x0)
[332376.812291] decode_attr_space_used: space used=4096
[332376.812878] decode_attr_time_access: atime=1762383044
[332376.813487] decode_attr_time_create: btime=1761952933
[332376.814098] decode_attr_time_metadata: ctime=1762055558
[332376.814895] decode_attr_time_modify: mtime=1762055558
[332376.815578] decode_attr_mounted_on_fileid: fileid=262146
[332376.816225] decode_getfattr_attrs: xdr returned 0
[332376.816796] decode_getfattr_generic: xdr returned 0
[332376.817374] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=64
[332376.818135] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[332376.818873] nfs4_free_slot: slotid 1 highest_used_slotid 0
[332376.819604] nfs41_sequence_process: Error 0 free the slot
[332376.820228] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[332376.820930] NFS: nfs_update_inode(0:58/262146 fh_crc=0xad8c294c ct=2 info=0x4427e7f)
[332376.821767] NFS: (0:58/262146) revalidation complete
[332376.822342] NFS: nfs_weak_revalidate: inode 262146 is valid
[332376.823056] NFS: permission(0:58/262146), mask=0x24, res=0
[332376.823684] NFS: open dir(/)
[332376.824087] NFS: readdir(/) starting at cookie 0
[332376.824641] _nfs4_proc_readdir: dentry = /, cookie = 0
[332376.825229] --> nfs41_call_sync_prepare data->seq_server 00000000e22b1bd9
[332376.825967] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=64
[332376.826814] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[332376.827616] RPC: gss_krb5_get_mic_v2
[332376.828114] encode_sequence: sessionid=1762048597:1479457708:22:0 seqid=28 slotid=0 max_slotid=0 cache_this=0
[332376.829146] encode_readdir: cookie = 0, verifier = 00000000:00000000, bitmap = 0018091a:00b4a23a:00000000
[332376.830144] RPC: gss_krb5_get_mic_v2
[332376.830720] RPC: xs_tcp_send_request(284) = 0
[332376.831431] RPC: gss_krb5_verify_mic_v2
[332376.831967] RPC: gss_krb5_verify_mic_v2
[332376.832498] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=64
[332376.833254] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
[332376.833994] nfs4_free_slot: slotid 1 highest_used_slotid 0
[332376.834695] nfs41_sequence_process: Error 0 free the slot
[332376.835318] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[332376.836016] _nfs4_proc_readdir: returns -5
[332376.836519] NFS: readdir(/) returns -5
Environment/Supporting Systems:
- The NFS server is a fresh Debian 13 cloud image. freeipa-client, gssproxy, nfs-kernel-server, and qemu-guest-agent have been installed. Joined to FreeIPA via ipa-client-install.
- Kerberos is provided by a newly installed FreeIPA instance on Fedora 43.
Failing NFS client configurations:
1. Freshly deployed and updated Debian 13 official cloud image (debian-13-genericcloud-amd64). freeipa-client, gssproxy, nfs-common, and qemu-guest-agent have been installed. Joined to FreeIPA via ipa-client-install.
2. Freshly installed Debian sid via mini ISO (2025-11-01). Same configuration as 1/above.
3. Minimal replication config: freshly installed Debian 13 via debian-13.1.0-amd64-netinst.iso . Installed nfs-common, krb5-config and krb5-user. Manually installed keytab: no additional krb5 configuration done (realm was automatically configured from hostname by krb5-config).
Working NFS client configuration:
- Fedora 43 installation configured via ipa-client-install .
This issue was escalated to me by someone with a matching production environment (FreeIPA on Fedora 43, and Debian 13 NFS client(s) and server). This original reporter also found that a Fedora 43 client worked as-expected with SHA2.
Miscellaneous observations:
- Testing was primarily conducted with NFS v4.2. Error occurs with krb5, krb5i and krb5p on 4.2. Also confirmed with krb5i on 4.1 and 4.0 (other combinations of krb5/krb5p and vers 4.1/4.0 not tested).
- readdir failure observed when client is mounted with NFS v4.2, 4.1, and 4.0. ls reports "input/output error" and dmesg reports "readdir(/) returns -5" in all 3 versions.
- When mounted with v4.1 and 4.0, cat'ing a file also fails with SHA2. There is no obvious (to me) error in dmesg. stat/touch of files and directories remains working.
- Failing state is cached on the client: if a user runs ls with a SHA2 session key, then acquires a new SHA1 session key ticket, the "input/output error" persists unless the NFS share is remounted. Setting noac, actimeo=0, and lookupcache=none mount options do not affect this behavior: the error persists until a remount. Error persisted when left overnight (about 13 hours).
- Cursory examination of a packet capture shows an apparently normal NFSv4 readdir call and reply. The reply contains the expected directory listing.
Attempted file/directory operations with SHA2 session key and sec=krb5i:
(all are successful/OK with SHA1 session key)
ls directory:
4.2: "Input/output error"
4.1: "Input/output error"
4.0: "Input/output error"
stat file and directory:
4.2: OK
4.1: OK
4.0: OK
touch file and directory:
4.2: OK
4.1: OK
4.0: OK
cat file:
4.2: OK
4.1: "Input/output error"
4.0: "Input/output error"
-- 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
-- /etc/default/nfs-common --
NEED_STATD=
NEED_IDMAPD=
NEED_GSSD=
-- /etc/nfs.conf --
[general]
pipefs-directory=/run/rpc_pipefs
[nfsrahead]
[exports]
[exportfs]
[gssd]
use-gss-proxy=1
[lockd]
[exportd]
[mountd]
manage-gids=y
[nfsdcld]
[nfsd]
[statd]
[sm-notify]
[svcgssd]
-- /etc/nfs.conf.d/*.conf --
-- System Information:
Debian Release: forky/sid
APT prefers unstable
APT policy: (500, 'unstable')
Architecture: amd64 (x86_64)
Kernel: Linux 6.17.7+deb14+1-amd64 (SMP w/4 CPU threads; PREEMPT)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled
Versions of packages nfs-common depends on:
ii adduser 3.153
ii init-system-helpers 1.69
ii keyutils 1.6.3-6
ii libc6 2.41-12
ii libcap2 1:2.75-10+b1
ii libcom-err2 1.47.2-3+b3
ii libdevmapper1.02.1 2:1.02.205-2
ii libevent-core-2.1-7t64 2.1.12-stable-10+b1
ii libgssapi-krb5-2 1.21.3-5
ii libk5crypto3 1.21.3-5
ii libkeyutils1 1.6.3-6
ii libkrb5-3 1.21.3-5
ii libmount1 2.41.2-4
ii libnfsidmap1 1:2.8.4-1+b1
ii libtirpc3t64 1.3.6+ds-1
ii libwrap0 7.6.q-36
ii rpcbind 1.2.7-1
ii ucf 3.0052
Versions of packages nfs-common recommends:
ii python3 3.13.7-1
Versions of packages nfs-common suggests:
pn open-iscsi <none>
pn watchdog <none>
-- no debconf information
[toc] | [next] | [standalone]
| From | Salvatore Bonaccorso <carnil@debian.org> |
|---|---|
| Date | 2025-11-13 06:10 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LQxKN-cAdz-1@gated-at.bofh.it> |
| In reply to | #90004 |
Hi NFS folks, Tyler W. Ross reported the following issue in Debian (in https://bugs.debian.org/1120598) On Wed, Nov 12, 2025 at 04:41:28PM -0500, Tyler W. Ross wrote: > Package: nfs-common > Version: 1:2.8.4-1+b1 > Severity: important > X-Debbugs-Cc: twr+debbugs@tylerwross.com > > > When the session key of a kerberos ticket uses a SHA2 cipher (aes256-cts-hmac-sha384-192 and aes128-cts-hmac-sha256-128 tested), readdir requests fail. > > SHA1 ciphers (aes256-cts-hmac-sha1-96 and aes128-cts-hmac-sha1-96 tested) work as expected. > > ls reports the following: > ls: reading directory '/mnt/example/': Input/output error > > stat and touch of files and directories is working, and cat'ing a file works (see also: later note about cat with NFSv4.1 and 4.0). > > > > Example of a non-working ticket, as reported by klist -e: > 11/12/25 18:37:30 11/13/25 17:49:03 nfs/nfssrv.ipa.twrlab.net@IPA.TWRLAB.NET > Etype (skey, tkt): aes256-cts-hmac-sha384-192, aes256-cts-hmac-sha384-192 > > Example of a working ticket: > 11/12/25 19:01:46 11/13/25 18:27:33 nfs/nfssrv.ipa.twrlab.net@IPA.TWRLAB.NET > Etype (skey, tkt): aes256-cts-hmac-sha1-96, aes256-cts-hmac-sha384-192 > > If rpcdebug is enabled for nfs and rpc modules, the following is logged to dmesg: > [332376.797836] NFS: nfs_weak_revalidate: inode 262146 is valid > [332376.798512] NFS: revalidating (0:58/262146) > [332376.799169] --> nfs41_call_sync_prepare data->seq_server 00000000e22b1bd9 > [332376.799916] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=64 > [332376.800764] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0 > [332376.801507] RPC: gss_krb5_get_mic_v2 > [332376.802009] encode_sequence: sessionid=1762048597:1479457708:22:0 seqid=27 slotid=0 max_slotid=0 cache_this=0 > [332376.803204] RPC: gss_krb5_get_mic_v2 > [332376.803726] RPC: xs_tcp_send_request(260) = 0 > [332376.804536] RPC: gss_krb5_verify_mic_v2 > [332376.805093] RPC: gss_krb5_verify_mic_v2 > [332376.805643] decode_attr_type: type=040000 > [332376.806149] decode_attr_change: change attribute=22 > [332376.806866] decode_attr_size: file size=4096 > [332376.807398] decode_attr_fsid: fsid=(0xfdcb5a40986843e0/0xa4fc6c44ad8345ad) > [332376.808154] decode_attr_fileid: fileid=262146 > [332376.808742] decode_attr_fs_locations: fs_locations done, error = 0 > [332376.809495] decode_attr_mode: file mode=0777 > [332376.810042] decode_attr_nlink: nlink=3 > [332376.810695] decode_attr_owner: uid=591200000 > [332376.811229] decode_attr_group: gid=591200004 > [332376.811761] decode_attr_rdev: rdev=(0x0:0x0) > [332376.812291] decode_attr_space_used: space used=4096 > [332376.812878] decode_attr_time_access: atime=1762383044 > [332376.813487] decode_attr_time_create: btime=1761952933 > [332376.814098] decode_attr_time_metadata: ctime=1762055558 > [332376.814895] decode_attr_time_modify: mtime=1762055558 > [332376.815578] decode_attr_mounted_on_fileid: fileid=262146 > [332376.816225] decode_getfattr_attrs: xdr returned 0 > [332376.816796] decode_getfattr_generic: xdr returned 0 > [332376.817374] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=64 > [332376.818135] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1 > [332376.818873] nfs4_free_slot: slotid 1 highest_used_slotid 0 > [332376.819604] nfs41_sequence_process: Error 0 free the slot > [332376.820228] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295 > [332376.820930] NFS: nfs_update_inode(0:58/262146 fh_crc=0xad8c294c ct=2 info=0x4427e7f) > [332376.821767] NFS: (0:58/262146) revalidation complete > [332376.822342] NFS: nfs_weak_revalidate: inode 262146 is valid > [332376.823056] NFS: permission(0:58/262146), mask=0x24, res=0 > [332376.823684] NFS: open dir(/) > [332376.824087] NFS: readdir(/) starting at cookie 0 > [332376.824641] _nfs4_proc_readdir: dentry = /, cookie = 0 > [332376.825229] --> nfs41_call_sync_prepare data->seq_server 00000000e22b1bd9 > [332376.825967] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=64 > [332376.826814] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0 > [332376.827616] RPC: gss_krb5_get_mic_v2 > [332376.828114] encode_sequence: sessionid=1762048597:1479457708:22:0 seqid=28 slotid=0 max_slotid=0 cache_this=0 > [332376.829146] encode_readdir: cookie = 0, verifier = 00000000:00000000, bitmap = 0018091a:00b4a23a:00000000 > [332376.830144] RPC: gss_krb5_get_mic_v2 > [332376.830720] RPC: xs_tcp_send_request(284) = 0 > [332376.831431] RPC: gss_krb5_verify_mic_v2 > [332376.831967] RPC: gss_krb5_verify_mic_v2 > [332376.832498] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=64 > [332376.833254] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1 > [332376.833994] nfs4_free_slot: slotid 1 highest_used_slotid 0 > [332376.834695] nfs41_sequence_process: Error 0 free the slot > [332376.835318] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295 > [332376.836016] _nfs4_proc_readdir: returns -5 > [332376.836519] NFS: readdir(/) returns -5 > > > > Environment/Supporting Systems: > - The NFS server is a fresh Debian 13 cloud image. freeipa-client, gssproxy, nfs-kernel-server, and qemu-guest-agent have been installed. Joined to FreeIPA via ipa-client-install. > - Kerberos is provided by a newly installed FreeIPA instance on Fedora 43. > > Failing NFS client configurations: > 1. Freshly deployed and updated Debian 13 official cloud image (debian-13-genericcloud-amd64). freeipa-client, gssproxy, nfs-common, and qemu-guest-agent have been installed. Joined to FreeIPA via ipa-client-install. > 2. Freshly installed Debian sid via mini ISO (2025-11-01). Same configuration as 1/above. > 3. Minimal replication config: freshly installed Debian 13 via debian-13.1.0-amd64-netinst.iso . Installed nfs-common, krb5-config and krb5-user. Manually installed keytab: no additional krb5 configuration done (realm was automatically configured from hostname by krb5-config). > > Working NFS client configuration: > - Fedora 43 installation configured via ipa-client-install . > > This issue was escalated to me by someone with a matching production environment (FreeIPA on Fedora 43, and Debian 13 NFS client(s) and server). This original reporter also found that a Fedora 43 client worked as-expected with SHA2. > > > > Miscellaneous observations: > - Testing was primarily conducted with NFS v4.2. Error occurs with krb5, krb5i and krb5p on 4.2. Also confirmed with krb5i on 4.1 and 4.0 (other combinations of krb5/krb5p and vers 4.1/4.0 not tested). > - readdir failure observed when client is mounted with NFS v4.2, 4.1, and 4.0. ls reports "input/output error" and dmesg reports "readdir(/) returns -5" in all 3 versions. > - When mounted with v4.1 and 4.0, cat'ing a file also fails with SHA2. There is no obvious (to me) error in dmesg. stat/touch of files and directories remains working. > - Failing state is cached on the client: if a user runs ls with a SHA2 session key, then acquires a new SHA1 session key ticket, the "input/output error" persists unless the NFS share is remounted. Setting noac, actimeo=0, and lookupcache=none mount options do not affect this behavior: the error persists until a remount. Error persisted when left overnight (about 13 hours). > - Cursory examination of a packet capture shows an apparently normal NFSv4 readdir call and reply. The reply contains the expected directory listing. > > Attempted file/directory operations with SHA2 session key and sec=krb5i: > (all are successful/OK with SHA1 session key) > ls directory: > 4.2: "Input/output error" > 4.1: "Input/output error" > 4.0: "Input/output error" > stat file and directory: > 4.2: OK > 4.1: OK > 4.0: OK > touch file and directory: > 4.2: OK > 4.1: OK > 4.0: OK > cat file: > 4.2: OK > 4.1: "Input/output error" > 4.0: "Input/output error" > > > > > -- 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 > -- /etc/default/nfs-common -- > NEED_STATD= > NEED_IDMAPD= > NEED_GSSD= > -- /etc/nfs.conf -- > [general] > pipefs-directory=/run/rpc_pipefs > [nfsrahead] > [exports] > [exportfs] > [gssd] > use-gss-proxy=1 > [lockd] > [exportd] > [mountd] > manage-gids=y > [nfsdcld] > [nfsd] > [statd] > [sm-notify] > [svcgssd] > -- /etc/nfs.conf.d/*.conf -- > > -- System Information: > Debian Release: forky/sid > APT prefers unstable > APT policy: (500, 'unstable') > Architecture: amd64 (x86_64) > > Kernel: Linux 6.17.7+deb14+1-amd64 (SMP w/4 CPU threads; PREEMPT) > Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE not set > Shell: /bin/sh linked to /usr/bin/dash > Init: systemd (via /run/systemd/system) > LSM: AppArmor: enabled Is there anything which could help us debugging this? Regards, Salvatore
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-13 18:20 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LQJ9g-cHSX-3@gated-at.bofh.it> |
| In reply to | #90004 |
Thanks, Chunk.
Suggested trace-cmd report from the client follows. Last 3 lines appear salient, but I've included the full report just in case.
cpus=4
ls-969 [003] ..... 270.318649: nfs_getattr_enter: fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ..... 270.318651: nfs_getattr_exit: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ..... 270.318654: nfs_revalidate_inode_enter: fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ..... 270.318658: rpc_task_begin: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=0x4 status=0 action=0x0
ls-969 [003] ..... 270.318658: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_prepare_task
ls-969 [003] ..... 270.318660: nfs4_setup_sequence: session=0x5988ad3c slot_nr=0 seq_nr=24 highest_used_slotid=0
ls-969 [003] ..... 270.318661: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_start
ls-969 [003] ..... 270.318661: rpc_request: task:00000006@00000005 nfsv4 GETATTR (sync)
ls-969 [003] ..... 270.318662: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_reserve
ls-969 [003] ..... 270.318663: xprt_reserve: task:00000006@00000005 xid=0x79569c7a
ls-969 [003] ..... 270.318663: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_reserveresult
ls-969 [003] ..... 270.318663: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_refresh
rpc.gssd-613 [001] ..... 270.318690: rpcgss_upcall_msg: msg='mech=krb5 uid=591200003 enctypes=20,19,18,17'
rpc.gssd-970 [002] ..... 270.326582: rpcgss_context: win_size=128 expiry=4316009978 now=4294959728 timeout=84201 acceptor=nfs@nfssrv.ipa.twrlab.net
ls-969 [003] ...1. 270.326598: rpcgss_ctx_init: cred=0xffff8895c5989900 service=integrity principal='(null)'
ls-969 [003] ..... 270.326600: rpcgss_upcall_result: for uid 591200003, result=0
ls-969 [003] ..... 270.326601: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_refreshresult
ls-969 [003] ..... 270.326601: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_allocate
ls-969 [003] ..... 270.326603: rpc_buf_alloc: task:00000006@00000005 callsize=1844 recvsize=2704 status=0
ls-969 [003] ..... 270.326603: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_encode
ls-969 [003] ..... 270.326604: rpcgss_seqno: task:00000006@00000005 xid=0x79569c7a seqno=1
ls-969 [003] ..... 270.326611: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x1c status=0 action=call_transmit
ls-969 [003] ...1. 270.326611: xprt_reserve_xprt: task:00000006@00000005 snd_task:00000006
ls-969 [003] ..... 270.326612: rpcgss_need_reencode: task:00000006@00000005 xid=0x79569c7a rq_seqno=1 seq_xmit=0 reencode unneeded
ls-969 [003] ..... 270.326612: rpc_xdr_sendto: task:00000006@00000005 head=[0xffff8895c29fe008,260] page=0(0) tail=[(nil),0] len=260
ls-969 [003] ..... 270.326627: xprt_transmit: task:00000006@00000005 xid=0x79569c7a seqno=1 status=0
ls-969 [003] ...1. 270.326628: xprt_release_xprt: task:00000006@00000005 snd_task:ffffffff
ls-969 [003] ..... 270.326629: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x14 status=0 action=call_transmit_status
ls-969 [003] ...2. 270.326629: rpc_task_sleep: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x14 status=0 timeout=0 queue=xprt_pending
ls-969 [003] ..... 270.326630: rpc_task_sync_sleep: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=0x16 status=0 action=call_status
<idle>-0 [001] ..s2. 270.326754: xs_data_ready: peer=[10.108.2.102]:2049
kworker/u16:0-12 [001] ...1. 270.326762: xprt_lookup_rqst: peer=[10.108.2.102]:2049 xid=0x79569c7a status=0
kworker/u16:0-12 [001] ...2. 270.326764: rpc_task_wakeup: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=0x6 status=0 timeout=15000 queue=xprt_pending
kworker/u16:0-12 [001] ..... 270.326768: xs_stream_read_request: peer=[10.108.2.102]:2049 xid=0x79569c7a copied=384 reclen=384 offset=384
kworker/u16:0-12 [001] ..... 270.326769: xs_stream_read_data: peer=[10.108.2.102]:2049 err=-11 total=388
ls-969 [003] ..... 270.326775: rpc_task_sync_wake: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.326775: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=xprt_timer
ls-969 [003] ..... 270.326775: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.326775: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_decode
ls-969 [003] ..... 270.326776: rpc_xdr_recvfrom: task:00000006@00000005 head=[0xffff8895c29fe73c,2704] page=0(0) tail=[(nil),0] len=384
ls-969 [003] ..... 270.326785: nfs4_map_name_to_uid: error=0 (OK) id=591200000 name=admin@ipa.twrlab.net
ls-969 [003] ..... 270.326786: nfs4_map_group_to_gid: error=0 (OK) id=591200004 name=domainusers@ipa.twrlab.net
ls-969 [003] ..... 270.326787: rpc_task_run_action: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task
ls-969 [003] ..... 270.326787: rpc_task_end: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task
ls-969 [003] ..... 270.326788: rpc_stats_latency: task:00000006@00000005 xid=0x79569c7a nfsv4 GETATTR backlog=7956 rtt=149 execute=8131 xprt_id=1
ls-969 [003] ..... 270.326789: rpc_task_call_done: task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=nfs41_call_sync_done
ls-969 [003] ..... 270.326789: nfs4_sequence_done: error=0 (OK) session=0x5988ad3c slot_nr=0 seq_nr=24 highest_slotid=63 target_highest_slotid=63 status_flags=0x0 ()
ls-969 [003] ...1. 270.326791: xprt_release_xprt: task:00000006@00000005 snd_task:ffffffff
ls-969 [003] ..... 270.326793: nfs4_getattr: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c valid=TYPE|MODE|NLINK|OWNER|GROUP|RDEV|SIZE|FSID|FILEID|ATIME|MTIME|CTIME|CHANGE|BTIME|0x40020
0
ls-969 [003] ...1. 270.326795: nfs_refresh_inode_enter: fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ...1. 270.326797: nfs_set_cache_invalid: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ...1. 270.326797: nfs_refresh_inode_exit: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ..... 270.326798: nfs_revalidate_inode_exit: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ..... 270.326799: nfs_access_enter: fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ..... 270.326801: rpc_task_begin: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=0x4 status=0 action=0x0
ls-969 [003] ..... 270.326801: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_prepare_task
ls-969 [003] ..... 270.326801: nfs4_setup_sequence: session=0x5988ad3c slot_nr=0 seq_nr=25 highest_used_slotid=0
ls-969 [003] ..... 270.326802: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_start
ls-969 [003] ..... 270.326802: rpc_request: task:00000007@00000005 nfsv4 ACCESS (sync)
ls-969 [003] ..... 270.326802: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_reserve
ls-969 [003] ..... 270.326803: xprt_reserve: task:00000007@00000005 xid=0x7a569c7a
ls-969 [003] ..... 270.326803: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_reserveresult
ls-969 [003] ..... 270.326803: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_refresh
ls-969 [003] ..... 270.326804: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_refreshresult
ls-969 [003] ..... 270.326804: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_allocate
ls-969 [003] ..... 270.326804: rpc_buf_alloc: task:00000007@00000005 callsize=1836 recvsize=2712 status=0
ls-969 [003] ..... 270.326804: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_encode
ls-969 [003] ..... 270.326805: rpcgss_seqno: task:00000007@00000005 xid=0x7a569c7a seqno=2
ls-969 [003] ..... 270.326807: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x1c status=0 action=call_transmit
ls-969 [003] ...1. 270.326807: xprt_reserve_xprt: task:00000007@00000005 snd_task:00000007
ls-969 [003] ..... 270.326808: rpcgss_need_reencode: task:00000007@00000005 xid=0x7a569c7a rq_seqno=2 seq_xmit=1 reencode unneeded
ls-969 [003] ..... 270.326808: rpc_xdr_sendto: task:00000007@00000005 head=[0xffff8895c29fe008,268] page=0(0) tail=[(nil),0] len=268
ls-969 [003] ..... 270.326816: xprt_transmit: task:00000007@00000005 xid=0x7a569c7a seqno=2 status=0
ls-969 [003] ...1. 270.326817: xprt_release_xprt: task:00000007@00000005 snd_task:ffffffff
ls-969 [003] ..... 270.326817: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x14 status=0 action=call_transmit_status
ls-969 [003] ...2. 270.326817: rpc_task_sleep: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x14 status=0 timeout=0 queue=xprt_pending
ls-969 [003] ..... 270.326817: rpc_task_sync_sleep: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=0x16 status=0 action=call_status
<idle>-0 [001] ..s2. 270.326882: xs_data_ready: peer=[10.108.2.102]:2049
kworker/u16:0-12 [001] ...1. 270.326885: xprt_lookup_rqst: peer=[10.108.2.102]:2049 xid=0x7a569c7a status=0
kworker/u16:0-12 [001] ...2. 270.326885: rpc_task_wakeup: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=0x6 status=0 timeout=15000 queue=xprt_pending
kworker/u16:0-12 [001] ..... 270.326888: xs_stream_read_request: peer=[10.108.2.102]:2049 xid=0x7a569c7a copied=260 reclen=260 offset=260
kworker/u16:0-12 [001] ..... 270.326888: xs_stream_read_data: peer=[10.108.2.102]:2049 err=-11 total=264
ls-969 [003] ..... 270.326895: rpc_task_sync_wake: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.326895: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=xprt_timer
ls-969 [003] ..... 270.326895: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.326895: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_decode
ls-969 [003] ..... 270.326895: rpc_xdr_recvfrom: task:00000007@00000005 head=[0xffff8895c29fe734,2712] page=0(0) tail=[(nil),0] len=260
ls-969 [003] ..... 270.326898: rpc_task_run_action: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task
ls-969 [003] ..... 270.326898: rpc_task_end: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task
ls-969 [003] ..... 270.326899: rpc_stats_latency: task:00000007@00000005 xid=0x7a569c7a nfsv4 ACCESS backlog=7 rtt=76 execute=98 xprt_id=1
ls-969 [003] ..... 270.326899: rpc_task_call_done: task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=nfs41_call_sync_done
ls-969 [003] ..... 270.326899: nfs4_sequence_done: error=0 (OK) session=0x5988ad3c slot_nr=0 seq_nr=25 highest_slotid=63 target_highest_slotid=63 status_flags=0x0 ()
ls-969 [003] ...1. 270.326900: xprt_release_xprt: task:00000007@00000005 snd_task:ffffffff
ls-969 [003] ...1. 270.326901: nfs_refresh_inode_enter: fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ...1. 270.326901: nfs_set_cache_invalid: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ...1. 270.326901: nfs_refresh_inode_exit: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ..... 270.326902: nfs4_access: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c
ls-969 [003] ..... 270.326903: nfs_access_exit: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x0 () nfs_flags=0x4 (ACL_LRU_SET) mask=0x24 permitted=0x7
ls-969 [003] ..... 270.326907: nfs_getattr_enter: fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ..... 270.326908: nfs_getattr_exit: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x0 () nfs_flags=0x4 (ACL_LRU_SET)
ls-969 [003] ..... 270.326928: nfs_readdir_cache_fill: fileid=00:2d:262146 fhandle=0xad8c294c version=31 cookie=0000000000000000:0x0 cache_index=0 dtsize=4096
ls-969 [003] ..... 270.326931: rpc_task_begin: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=0x4 status=0 action=0x0
ls-969 [003] ..... 270.326931: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_prepare_task
ls-969 [003] ..... 270.326931: nfs4_setup_sequence: session=0x5988ad3c slot_nr=0 seq_nr=26 highest_used_slotid=0
ls-969 [003] ..... 270.326931: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_start
ls-969 [003] ..... 270.326932: rpc_request: task:00000008@00000005 nfsv4 READDIR (sync)
ls-969 [003] ..... 270.326932: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_reserve
ls-969 [003] ..... 270.326932: xprt_reserve: task:00000008@00000005 xid=0x7b569c7a
ls-969 [003] ..... 270.326932: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_reserveresult
ls-969 [003] ..... 270.326932: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_refresh
ls-969 [003] ..... 270.326933: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_refreshresult
ls-969 [003] ..... 270.326933: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_allocate
ls-969 [003] ..... 270.326933: rpc_buf_alloc: task:00000008@00000005 callsize=3932 recvsize=176 status=0
ls-969 [003] ..... 270.326933: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_encode
ls-969 [003] ..... 270.326934: rpcgss_seqno: task:00000008@00000005 xid=0x7b569c7a seqno=3
ls-969 [003] ..... 270.326936: rpc_xdr_reply_pages: task:00000008@00000005 head=[0xffff8895c29fef64,140] page=4008(88) tail=[0xffff8895c29feff0,36] len=0
ls-969 [003] ..... 270.326937: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=RUNNING|0x1c status=0 action=call_transmit
ls-969 [003] ...1. 270.326937: xprt_reserve_xprt: task:00000008@00000005 snd_task:00000008
ls-969 [003] ..... 270.326937: rpcgss_need_reencode: task:00000008@00000005 xid=0x7b569c7a rq_seqno=3 seq_xmit=2 reencode unneeded
ls-969 [003] ..... 270.326938: rpc_xdr_sendto: task:00000008@00000005 head=[0xffff8895c29fe008,284] page=0(0) tail=[(nil),0] len=284
ls-969 [003] ..... 270.326946: xprt_transmit: task:00000008@00000005 xid=0x7b569c7a seqno=3 status=0
ls-969 [003] ...1. 270.326947: xprt_release_xprt: task:00000008@00000005 snd_task:ffffffff
ls-969 [003] ..... 270.326947: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x14 status=0 action=call_transmit_status
ls-969 [003] ...2. 270.326947: rpc_task_sleep: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x14 status=0 timeout=0 queue=xprt_pending
ls-969 [003] ..... 270.326947: rpc_task_sync_sleep: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=0x16 status=0 action=call_status
<idle>-0 [001] ..s2. 270.327040: xs_data_ready: peer=[10.108.2.102]:2049
kworker/u16:0-12 [001] ...1. 270.327048: xprt_lookup_rqst: peer=[10.108.2.102]:2049 xid=0x7b569c7a status=0
kworker/u16:0-12 [001] ...2. 270.327050: rpc_task_wakeup: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=0x6 status=0 timeout=15000 queue=xprt_pending
kworker/u16:0-12 [001] ..... 270.327054: xs_stream_read_request: peer=[10.108.2.102]:2049 xid=0x7b569c7a copied=988 reclen=988 offset=988
kworker/u16:0-12 [001] ..... 270.327055: xs_stream_read_data: peer=[10.108.2.102]:2049 err=-11 total=992
ls-969 [003] ..... 270.327062: rpc_task_sync_wake: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.327062: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=xprt_timer
ls-969 [003] ..... 270.327063: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.327063: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_decode
ls-969 [003] ..... 270.327063: rpc_xdr_recvfrom: task:00000008@00000005 head=[0xffff8895c29fef64,140] page=4008(88) tail=[0xffff8895c29feff0,36] len=988
ls-969 [003] ..... 270.327067: rpc_xdr_overflow: task:00000008@00000005 nfsv4 READDIR requested=8 p=0xffff8895c29fefec end=0xffff8895c29feff0 xdr=[0xffff8895c29fef64,140]/4008/[0xffff8895c29feff0,36]/988
ls-969 [003] ..... 270.327068: rpc_task_run_action: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=-5 action=rpc_exit_task
ls-969 [003] ..... 270.327068: rpc_task_end: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=-5 action=rpc_exit_task
ls-969 [003] ..... 270.327068: rpc_stats_latency: task:00000008@00000005 xid=0x7b569c7a nfsv4 READDIR backlog=7 rtt=110 execute=137 xprt_id=1
ls-969 [003] ..... 270.327068: rpc_task_call_done: task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=-5 action=nfs41_call_sync_done
ls-969 [003] ..... 270.327068: nfs4_sequence_done: error=0 (OK) session=0x5988ad3c slot_nr=0 seq_nr=26 highest_slotid=63 target_highest_slotid=63 status_flags=0x0 ()
ls-969 [003] ...1. 270.327069: xprt_release_xprt: task:00000008@00000005 snd_task:ffffffff
ls-969 [003] ...1. 270.327070: nfs_set_cache_invalid: error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x4 (INVALID_ATIME) nfs_flags=0x4 (ACL_LRU_SET)
ls-969 [003] ..... 270.327070: nfs4_readdir: error=-5 (EIO) fileid=00:2d:262146 fhandle=0xad8c294c
ls-969 [003] ..... 270.327071: nfs_readdir_cache_fill_done: error=-5 (IO) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096 cache_validity=0x4 (INVALID_ATIME) nfs_flags=0x4 (ACL_LRU_SET)
TWR
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-13 19:10 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LQJVD-cIsP-1@gated-at.bofh.it> |
| In reply to | #90004 |
On Thursday, November 13th, 2025 at 10:47 AM, Chuck Lever <chuck.lever@oracle.com> wrote: > > ls-969 [003] ..... 270.327063: rpc_xdr_recvfrom: task:00000008@00000005 head=[0xffff8895c29fef64,140] page=4008(88) tail=[0xffff8895c29feff0,36] len=988 > > ls-969 [003] ..... 270.327067: rpc_xdr_overflow: task:00000008@00000005 nfsv4 READDIR requested=8 p=0xffff8895c29fefec end=0xffff8895c29feff0 xdr=[0xffff8895c29fef64,140]/4008/[0xffff8895c29feff0,36]/988 > > > Here's the problem. This is a sign of an XDR decoding issue. If you > capture the traffic with Wireshark, does Wireshark indicate where the > XDR is malformed? Wireshark appears to decode the READDIR reply without issue. Nothing is obviously marked as malformed, and values all appear sane when spot-checking fields in the decoded packet. TWR
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-13 20:00 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LQKI1-cIMi-5@gated-at.bofh.it> |
| In reply to | #90004 |
On Thursday, November 13th, 2025 at 11:12 AM, Chuck Lever <chuck.lever@oracle.com> wrote: > Then I would start looking for differences between the Debian 13 and > Fedora 43 kernel code base under net/sunrpc/ . > > Alternatively, "git bisect first, ask questions later" ... :-) This is outside my day-to-day, so I don't have a workflow for this kind of testing/debugging, but I'll see what I can do. Thanks for the starting place. > So I didn't find an indication of whether this was sec=krb5, sec=krb5i, > or sec=krb5p. That might narrow down where the code changed. I confirmed the issue with all 3 krb5 sec modes, in both the 6.12 kernel that ships with Debian 13 and the 6.17 that currently ships with Debian Sid/unstable. Similarly, I confirmed NFSv4.2, 4.1 and 4.0 are impacted. > Also, the xdr_buf might have a page boundary positioned in the middle of > an XDR data item. Knowing which data item is being decoded where the > "overflow" occurs might be helpful (I think adding pr_info() call sites > or trace_printk() will be adequate to gain some better observability). No experience with kernel hacking, so I'm not confident I can locate meaningful places to insert those. I'll see where some snooping and a bisect gets me. Failing that, if anyone has recommendations on where to add those calls, I'd appreciate the guidance. TWR
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-14 05:40 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LQTLj-cP9F-1@gated-at.bofh.it> |
| In reply to | #90004 |
I tried a couple vanilla/stock kernels today, without success.
Most notably, I built 6.17.8 from upstream using the Kconfig from the
working Fedora 43 client in my lab ("config-6.17.5-300.fc43.x86_64").
Unfortunately, the rpc_xdr_overflow still occurs with this kernel.
TWR
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-14 06:20 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LQUo1-cPF1-3@gated-at.bofh.it> |
| In reply to | #90022 |
On Thursday, November 13th, 2025 at 9:35 PM, Tyler W. Ross <TWR@tylerwross.com> wrote:
> I tried a couple vanilla/stock kernels today, without success.
>
> Most notably, I built 6.17.8 from upstream using the Kconfig from the
> working Fedora 43 client in my lab ("config-6.17.5-300.fc43.x86_64").
>
> Unfortunately, the rpc_xdr_overflow still occurs with this kernel.
Quick addendum:
I had not tried Debian 12, because CONFIG_RPCSEC_GSS_KRB5_ENCTYPES_AES_SHA2
was not enabled in the shipped Kconfig.
I just spun up a Debian 12 VM and installed the aforementioned
upstream 6.17.8 with Fedora 43 Kconfig kernel and confirmed the issue
also occurs on Debian 12.
TWR
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-16 01:50 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LRz7P-dhgS-1@gated-at.bofh.it> |
| In reply to | #90004 |
On Friday, November 14th, 2025 at 7:19 AM, Chuck Lever <chuck.lever@oracle.com> wrote: > Then I would say further hunting for the broken commit is going to be > fruitless. Adding the WARNs in net/sunrpc/xdr.c is a good next step so > we see which XDR data item (assuming it's the same one every time) is > failing to decode. I added WARNs after each trace_rpc_xdr_overflow() call, and then a couple pr_info() inside xdr_copy_to_scratch() as a follow-up. If I'm understanding correctly, it's failing in the xdr_copy_to_scratch() call inside xdr_inline_decode(), because the xdr_stream struct has an unset/NULL scratch kvec. I don't understand the context enough to speculate on why, though. [ 26.844102] Entered xdr_copy_to_scratch() [ 26.844105] xdr->scratch.iov_base: 0000000000000000 [ 26.844107] xdr->scratch.iov_len: 0 [ 26.844127] ------------[ cut here ]------------ [ 26.844128] WARNING: CPU: 1 PID: 886 at net/sunrpc/xdr.c:1490 xdr_inline_decode.cold+0x65/0x141 [sunrpc] [ 26.844153] Modules linked in: rpcsec_gss_krb5 nfsv4 dns_resolver nfs lockd grace netfs binfmt_misc intel_rapl_msr intel_rapl_common kvm_amd ccp kvm cfg80211 hid_generic usbhid hid irqbypass rfkill ghash_clmulni_intel aesni_intel pcspkr 8021q garp stp virtio_balloon llc mrp button evdev joydev sg auth_rpcgss sunrpc configfs efi_pstore nfnetlink vsock_loopback vmw_vsock_virtio_transport_common vmw_vsock_vmci_transport vsock vmw_vmci qemu_fw_cfg ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 crc32c_cryptoapi sr_mod cdrom bochs uhci_hcd drm_client_lib drm_shmem_helper ehci_pci ata_generic sd_mod drm_kms_helper ehci_hcd ata_piix libata drm virtio_net usbcore virtio_scsi floppy psmouse net_failover failover scsi_mod serio_raw i2c_piix4 usb_common scsi_common i2c_smbus [ 26.844217] CPU: 1 UID: 591200003 PID: 886 Comm: ls Not tainted 6.17.8-debbug1120598hack3 #9 PREEMPT(lazy) [ 26.844220] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014 [ 26.844222] RIP: 0010:xdr_inline_decode.cold+0x65/0x141 [sunrpc] [ 26.844238] Code: 24 48 c7 c7 e7 eb 8c c0 48 8b 71 28 e8 5a 36 fc d7 48 8b 0c 24 4c 8b 44 24 10 48 8b 54 24 08 4c 39 41 28 73 0c 0f 1f 44 00 00 <0f> 0b e9 b7 fe fe ff 48 89 d8 48 89 cf 4c 89 44 24 08 48 29 d0 48 [ 26.844240] RSP: 0018:ffffd09e82ce3758 EFLAGS: 00010293 [ 26.844242] RAX: 0000000000000017 RBX: ffff8f1e0adcffe8 RCX: ffffd09e82ce3838 [ 26.844244] RDX: ffff8f1e0adcffe4 RSI: 0000000000000001 RDI: ffff8f1f37c5ce40 [ 26.844245] RBP: ffffd09e82ce37b4 R08: 0000000000000008 R09: ffffd09e82ce3600 [ 26.844246] R10: ffffffff9acdb348 R11: 00000000ffffefff R12: 000000000000001a [ 26.844247] R13: ffff8f1e01151200 R14: 0000000000000000 R15: 0000000000440000 [ 26.844250] FS: 00007fa5d13db240(0000) GS:ffff8f1f9c44a000(0000) knlGS:0000000000000000 [ 26.844252] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 26.844253] CR2: 00007fa5d13b9000 CR3: 000000010ab82000 CR4: 0000000000750ef0 [ 26.844255] PKRU: 55555554 [ 26.844257] Call Trace: [ 26.844259] <TASK> [ 26.844263] __decode_op_hdr+0x20/0x120 [nfsv4] [ 26.844288] nfs4_xdr_dec_readdir+0xbb/0x120 [nfsv4] [ 26.844305] gss_unwrap_resp+0x9e/0x150 [auth_rpcgss] [ 26.844311] call_decode+0x211/0x230 [sunrpc] [ 26.844332] ? __pfx_call_decode+0x10/0x10 [sunrpc] [ 26.844348] __rpc_execute+0xb6/0x480 [sunrpc] [ 26.844369] ? rpc_new_task+0x17a/0x200 [sunrpc] [ 26.844386] rpc_execute+0x133/0x160 [sunrpc] [ 26.844401] rpc_run_task+0x103/0x160 [sunrpc] [ 26.844419] nfs4_call_sync_sequence+0x74/0xb0 [nfsv4] [ 26.844440] _nfs4_proc_readdir+0x28d/0x310 [nfsv4] [ 26.844459] nfs4_proc_readdir+0x60/0xf0 [nfsv4] [ 26.844475] nfs_readdir_xdr_to_array+0x1fb/0x410 [nfs] [ 26.844494] nfs_readdir+0x2ed/0xf00 [nfs] [ 26.844506] iterate_dir+0xaa/0x270 [ 26.844517] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844521] __x64_sys_getdents64+0x7b/0x110 [ 26.844523] ? __pfx_filldir64+0x10/0x10 [ 26.844526] do_syscall_64+0x82/0x320 [ 26.844530] ? mod_memcg_lruvec_state+0xe7/0x2e0 [ 26.844533] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844535] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844537] ? __lruvec_stat_mod_folio+0x85/0xd0 [ 26.844539] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844541] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844550] ? set_ptes.isra.0+0x36/0x80 [ 26.844555] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844557] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844560] ? do_anonymous_page+0x101/0x970 [ 26.844563] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844565] ? ___pte_offset_map+0x1b/0x160 [ 26.844570] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844572] ? __handle_mm_fault+0xac6/0xef0 [ 26.844577] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844578] ? count_memcg_events+0xd6/0x220 [ 26.844581] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844583] ? handle_mm_fault+0x1d6/0x2d0 [ 26.844585] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844587] ? do_user_addr_fault+0x21a/0x690 [ 26.844591] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844593] ? srso_alias_return_thunk+0x5/0xfbef5 [ 26.844595] entry_SYSCALL_64_after_hwframe+0x76/0x7e [ 26.844597] RIP: 0033:0x7fa5d15678a3 [ 26.844606] Code: 8b 05 59 a5 10 00 64 c7 00 16 00 00 00 31 c0 eb 9e e8 11 03 04 00 90 b8 ff ff ff 7f 48 39 c2 48 0f 47 d0 b8 d9 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 05 c3 0f 1f 40 00 48 8b 15 21 a5 10 00 f7 d8 [ 26.844607] RSP: 002b:00007fffa272d848 EFLAGS: 00000293 ORIG_RAX: 00000000000000d9 [ 26.844609] RAX: ffffffffffffffda RBX: 00007fa5d13b9010 RCX: 00007fa5d15678a3 [ 26.844610] RDX: 0000000000020000 RSI: 00007fa5d13b9040 RDI: 0000000000000003 [ 26.844611] RBP: 00007fa5d13b9040 R08: 00007fa5d1707400 R09: 0000000000000000 [ 26.844613] R10: 0000000000000022 R11: 0000000000000293 R12: 00007fa5d13b9014 [ 26.844614] R13: fffffffffffffea0 R14: 0000000000000000 R15: 0000564585c1c200 [ 26.844617] </TASK> [ 26.844618] ---[ end trace 0000000000000000 ]--- TWR
[toc] | [prev] | [next] | [standalone]
| From | Trond Myklebust <trondmy@kernel.org> |
|---|---|
| Date | 2025-11-16 19:30 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LRPFD-ds93-1@gated-at.bofh.it> |
| In reply to | #90004 |
On Sun, 2025-11-16 at 11:29 -0500, Chuck Lever wrote: > On 11/15/25 7:38 PM, Tyler W. Ross wrote: > > On Friday, November 14th, 2025 at 7:19 AM, Chuck Lever > > <chuck.lever@oracle.com> wrote: > > > Then I would say further hunting for the broken commit is going > > > to be > > > fruitless. Adding the WARNs in net/sunrpc/xdr.c is a good next > > > step so > > > we see which XDR data item (assuming it's the same one every > > > time) is > > > failing to decode. > > > > I added WARNs after each trace_rpc_xdr_overflow() call, and then a > > couple > > pr_info() inside xdr_copy_to_scratch() as a follow-up. > > > > If I'm understanding correctly, it's failing in the > > xdr_copy_to_scratch() > > call inside xdr_inline_decode(), because the xdr_stream struct has > > an > > unset/NULL scratch kvec. I don't understand the context enough to > > speculate on why, though. > > > > [ 26.844102] Entered xdr_copy_to_scratch() > > [ 26.844105] xdr->scratch.iov_base: 0000000000000000 > > [ 26.844107] xdr->scratch.iov_len: 0 > > [ 26.844127] ------------[ cut here ]------------ > > [ 26.844128] WARNING: CPU: 1 PID: 886 at net/sunrpc/xdr.c:1490 > > xdr_inline_decode.cold+0x65/0x141 [sunrpc] > > [ 26.844153] Modules linked in: rpcsec_gss_krb5 nfsv4 > > dns_resolver nfs lockd grace netfs binfmt_misc intel_rapl_msr > > intel_rapl_common kvm_amd ccp kvm cfg80211 hid_generic usbhid hid > > irqbypass rfkill ghash_clmulni_intel aesni_intel pcspkr 8021q garp > > stp virtio_balloon llc mrp button evdev joydev sg auth_rpcgss > > sunrpc configfs efi_pstore nfnetlink vsock_loopback > > vmw_vsock_virtio_transport_common vmw_vsock_vmci_transport vsock > > vmw_vmci qemu_fw_cfg ip_tables x_tables autofs4 ext4 crc16 mbcache > > jbd2 crc32c_cryptoapi sr_mod cdrom bochs uhci_hcd drm_client_lib > > drm_shmem_helper ehci_pci ata_generic sd_mod drm_kms_helper > > ehci_hcd ata_piix libata drm virtio_net usbcore virtio_scsi floppy > > psmouse net_failover failover scsi_mod serio_raw i2c_piix4 > > usb_common scsi_common i2c_smbus > > [ 26.844217] CPU: 1 UID: 591200003 PID: 886 Comm: ls Not tainted > > 6.17.8-debbug1120598hack3 #9 PREEMPT(lazy) > > [ 26.844220] Hardware name: QEMU Standard PC (i440FX + PIIX, > > 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014 > > [ 26.844222] RIP: 0010:xdr_inline_decode.cold+0x65/0x141 [sunrpc] > > [ 26.844238] Code: 24 48 c7 c7 e7 eb 8c c0 48 8b 71 28 e8 5a 36 > > fc d7 48 8b 0c 24 4c 8b 44 24 10 48 8b 54 24 08 4c 39 41 28 73 0c > > 0f 1f 44 00 00 <0f> 0b e9 b7 fe fe ff 48 89 d8 48 89 cf 4c 89 44 24 > > 08 48 29 d0 48 > > [ 26.844240] RSP: 0018:ffffd09e82ce3758 EFLAGS: 00010293 > > [ 26.844242] RAX: 0000000000000017 RBX: ffff8f1e0adcffe8 RCX: > > ffffd09e82ce3838 > > [ 26.844244] RDX: ffff8f1e0adcffe4 RSI: 0000000000000001 RDI: > > ffff8f1f37c5ce40 > > [ 26.844245] RBP: ffffd09e82ce37b4 R08: 0000000000000008 R09: > > ffffd09e82ce3600 > > [ 26.844246] R10: ffffffff9acdb348 R11: 00000000ffffefff R12: > > 000000000000001a > > [ 26.844247] R13: ffff8f1e01151200 R14: 0000000000000000 R15: > > 0000000000440000 > > [ 26.844250] FS: 00007fa5d13db240(0000) > > GS:ffff8f1f9c44a000(0000) knlGS:0000000000000000 > > [ 26.844252] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > > [ 26.844253] CR2: 00007fa5d13b9000 CR3: 000000010ab82000 CR4: > > 0000000000750ef0 > > [ 26.844255] PKRU: 55555554 > > [ 26.844257] Call Trace: > > [ 26.844259] <TASK> > > [ 26.844263] __decode_op_hdr+0x20/0x120 [nfsv4] > > [ 26.844288] nfs4_xdr_dec_readdir+0xbb/0x120 [nfsv4] > > [ 26.844305] gss_unwrap_resp+0x9e/0x150 [auth_rpcgss] > > [ 26.844311] call_decode+0x211/0x230 [sunrpc] > > [ 26.844332] ? __pfx_call_decode+0x10/0x10 [sunrpc] > > [ 26.844348] __rpc_execute+0xb6/0x480 [sunrpc] > > [ 26.844369] ? rpc_new_task+0x17a/0x200 [sunrpc] > > [ 26.844386] rpc_execute+0x133/0x160 [sunrpc] > > [ 26.844401] rpc_run_task+0x103/0x160 [sunrpc] > > [ 26.844419] nfs4_call_sync_sequence+0x74/0xb0 [nfsv4] > > [ 26.844440] _nfs4_proc_readdir+0x28d/0x310 [nfsv4] > > [ 26.844459] nfs4_proc_readdir+0x60/0xf0 [nfsv4] > > [ 26.844475] nfs_readdir_xdr_to_array+0x1fb/0x410 [nfs] > > [ 26.844494] nfs_readdir+0x2ed/0xf00 [nfs] > > [ 26.844506] iterate_dir+0xaa/0x270 > > Hi Trond, Anna - > > NFSv4 READDIR is hitting an XDR overflow because the XDR stream's > scratch buffer is missing, and one of the READDIR response's fields > crosses a page boundary in the receive buffer. > > Shouldn't the client's readdir XDR decoder have a scratch buffer? No it shouldn't. The READDIR XDR decoder doesn't interpret the contents of the readdir buffer. What it is supposed to do is read the op header and the readdir verifier, and then to align the remaining data into the pages that were allocated as buffer using a call to xdr_read_page(). Essentially, it's the exact same procedure as we follow for a READ call. So if we're crossing into the pages before we hit the call to xdr_read_pages() then that means we've allocated too small a header buffer. Since it only appears to happen with RPCSEC_GSS, then my money would be on AUTH_GSS not padding the reply buffer sufficiently when setting the value of auth->au_cslack. -- Trond Myklebust Linux NFS client maintainer, Hammerspace trondmy@kernel.org, trond.myklebust@hammerspace.com
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-17 06:30 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LRZYl-dz0H-1@gated-at.bofh.it> |
| In reply to | #90084 |
Weird behavior I just discovered: Explicitly setting allowed-enctypes in the gssd section of /etc/nfs.conf to exclude aes256-cts-hmac-sha1-96 makes both SHA2 ciphers work as expected (assuming each is allowed). If allowed-enctypes is unset (letting gssd interrogate the kernel for supported enctypes) or includes aes256-cts-hmac-sha1-96, then the XDR overflow occurs. Non-working configurations (first is the commented-out default in nfs.conf): allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128,camellia256-cts-cmac,camellia128-cts-cmac,aes256-cts-hmac-sha1-96,aes128-cts-hmac-sha1-96 allowed-enctypes=aes256-cts-hmac-sha384-192,aes256-cts-hmac-sha1-96 allowed-enctypes=aes128-cts-hmac-sha256-128,aes256-cts-hmac-sha1-96 allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128,aes256-cts-hmac-sha1-96 Working configurations (first is default sans aes256-cts-hmac-sha1-96): allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128,camellia256-cts-cmac,camellia128-cts-cmac,aes128-cts-hmac-sha1-96 allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128 allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha1-96 allowed-enctypes=aes128-cts-hmac-sha256-128,aes128-cts-hmac-sha1-96 Is this gssd mishandling some setup/initialization? Or is there a miscalculation happening somewhere further up? TWR
[toc] | [prev] | [next] | [standalone]
| From | Scott Mayhew <smayhew@redhat.com> |
|---|---|
| Date | 2025-11-18 00:10 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LSgw9-dK5j-9@gated-at.bofh.it> |
| In reply to | #90101 |
On Mon, 17 Nov 2025, Tyler W. Ross wrote: > Weird behavior I just discovered: > > Explicitly setting allowed-enctypes in the gssd section of /etc/nfs.conf > to exclude aes256-cts-hmac-sha1-96 makes both SHA2 ciphers work as > expected (assuming each is allowed). > > If allowed-enctypes is unset (letting gssd interrogate the kernel for > supported enctypes) or includes aes256-cts-hmac-sha1-96, then the XDR > overflow occurs. > > Non-working configurations (first is the commented-out default in nfs.conf): > allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128,camellia256-cts-cmac,camellia128-cts-cmac,aes256-cts-hmac-sha1-96,aes128-cts-hmac-sha1-96 > allowed-enctypes=aes256-cts-hmac-sha384-192,aes256-cts-hmac-sha1-96 > allowed-enctypes=aes128-cts-hmac-sha256-128,aes256-cts-hmac-sha1-96 > allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128,aes256-cts-hmac-sha1-96 > > Working configurations (first is default sans aes256-cts-hmac-sha1-96): > allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128,camellia256-cts-cmac,camellia128-cts-cmac,aes128-cts-hmac-sha1-96 > allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128 > allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha1-96 > allowed-enctypes=aes128-cts-hmac-sha256-128,aes128-cts-hmac-sha1-96 > That doesn't really make sense. You should only need to use the allowed-enctypes setting if you're talking to an NFS server that doesn't have support for the new encryption types. It basically works like the "permitted_enctypes" option in krb5.conf, except it only affects NFS rather than affecting your krb5 configuration as a whole. Can you go back and re-do the tracepoint capture, except this time umount your NFS filessytems before starting the capture (i.e. perform the mount command while trace-cmd is running). I'm curious what values the rpcgss_update_slack tracepoint shows. > > Is this gssd mishandling some setup/initialization? > Or is there a miscalculation happening somewhere further up? > > > TWR >
[toc] | [prev] | [next] | [standalone]
| From | Scott Mayhew <smayhew@redhat.com> |
|---|---|
| Date | 2025-11-18 00:10 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LSgw9-dK5j-1@gated-at.bofh.it> |
| In reply to | #90084 |
On Sun, 16 Nov 2025, Trond Myklebust wrote:
> On Sun, 2025-11-16 at 11:29 -0500, Chuck Lever wrote:
> > On 11/15/25 7:38 PM, Tyler W. Ross wrote:
> > > On Friday, November 14th, 2025 at 7:19 AM, Chuck Lever
> > > <chuck.lever@oracle.com> wrote:
> > > > Then I would say further hunting for the broken commit is going
> > > > to be
> > > > fruitless. Adding the WARNs in net/sunrpc/xdr.c is a good next
> > > > step so
> > > > we see which XDR data item (assuming it's the same one every
> > > > time) is
> > > > failing to decode.
> > >
> > > I added WARNs after each trace_rpc_xdr_overflow() call, and then a
> > > couple
> > > pr_info() inside xdr_copy_to_scratch() as a follow-up.
> > >
> > > If I'm understanding correctly, it's failing in the
> > > xdr_copy_to_scratch()
> > > call inside xdr_inline_decode(), because the xdr_stream struct has
> > > an
> > > unset/NULL scratch kvec. I don't understand the context enough to
> > > speculate on why, though.
> > >
> > > [ 26.844102] Entered xdr_copy_to_scratch()
> > > [ 26.844105] xdr->scratch.iov_base: 0000000000000000
> > > [ 26.844107] xdr->scratch.iov_len: 0
> > > [ 26.844127] ------------[ cut here ]------------
> > > [ 26.844128] WARNING: CPU: 1 PID: 886 at net/sunrpc/xdr.c:1490
> > > xdr_inline_decode.cold+0x65/0x141 [sunrpc]
> > > [ 26.844153] Modules linked in: rpcsec_gss_krb5 nfsv4
> > > dns_resolver nfs lockd grace netfs binfmt_misc intel_rapl_msr
> > > intel_rapl_common kvm_amd ccp kvm cfg80211 hid_generic usbhid hid
> > > irqbypass rfkill ghash_clmulni_intel aesni_intel pcspkr 8021q garp
> > > stp virtio_balloon llc mrp button evdev joydev sg auth_rpcgss
> > > sunrpc configfs efi_pstore nfnetlink vsock_loopback
> > > vmw_vsock_virtio_transport_common vmw_vsock_vmci_transport vsock
> > > vmw_vmci qemu_fw_cfg ip_tables x_tables autofs4 ext4 crc16 mbcache
> > > jbd2 crc32c_cryptoapi sr_mod cdrom bochs uhci_hcd drm_client_lib
> > > drm_shmem_helper ehci_pci ata_generic sd_mod drm_kms_helper
> > > ehci_hcd ata_piix libata drm virtio_net usbcore virtio_scsi floppy
> > > psmouse net_failover failover scsi_mod serio_raw i2c_piix4
> > > usb_common scsi_common i2c_smbus
> > > [ 26.844217] CPU: 1 UID: 591200003 PID: 886 Comm: ls Not tainted
> > > 6.17.8-debbug1120598hack3 #9 PREEMPT(lazy)
> > > [ 26.844220] Hardware name: QEMU Standard PC (i440FX + PIIX,
> > > 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
> > > [ 26.844222] RIP: 0010:xdr_inline_decode.cold+0x65/0x141 [sunrpc]
> > > [ 26.844238] Code: 24 48 c7 c7 e7 eb 8c c0 48 8b 71 28 e8 5a 36
> > > fc d7 48 8b 0c 24 4c 8b 44 24 10 48 8b 54 24 08 4c 39 41 28 73 0c
> > > 0f 1f 44 00 00 <0f> 0b e9 b7 fe fe ff 48 89 d8 48 89 cf 4c 89 44 24
> > > 08 48 29 d0 48
> > > [ 26.844240] RSP: 0018:ffffd09e82ce3758 EFLAGS: 00010293
> > > [ 26.844242] RAX: 0000000000000017 RBX: ffff8f1e0adcffe8 RCX:
> > > ffffd09e82ce3838
> > > [ 26.844244] RDX: ffff8f1e0adcffe4 RSI: 0000000000000001 RDI:
> > > ffff8f1f37c5ce40
> > > [ 26.844245] RBP: ffffd09e82ce37b4 R08: 0000000000000008 R09:
> > > ffffd09e82ce3600
> > > [ 26.844246] R10: ffffffff9acdb348 R11: 00000000ffffefff R12:
> > > 000000000000001a
> > > [ 26.844247] R13: ffff8f1e01151200 R14: 0000000000000000 R15:
> > > 0000000000440000
> > > [ 26.844250] FS: 00007fa5d13db240(0000)
> > > GS:ffff8f1f9c44a000(0000) knlGS:0000000000000000
> > > [ 26.844252] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > [ 26.844253] CR2: 00007fa5d13b9000 CR3: 000000010ab82000 CR4:
> > > 0000000000750ef0
> > > [ 26.844255] PKRU: 55555554
> > > [ 26.844257] Call Trace:
> > > [ 26.844259] <TASK>
> > > [ 26.844263] __decode_op_hdr+0x20/0x120 [nfsv4]
> > > [ 26.844288] nfs4_xdr_dec_readdir+0xbb/0x120 [nfsv4]
> > > [ 26.844305] gss_unwrap_resp+0x9e/0x150 [auth_rpcgss]
> > > [ 26.844311] call_decode+0x211/0x230 [sunrpc]
> > > [ 26.844332] ? __pfx_call_decode+0x10/0x10 [sunrpc]
> > > [ 26.844348] __rpc_execute+0xb6/0x480 [sunrpc]
> > > [ 26.844369] ? rpc_new_task+0x17a/0x200 [sunrpc]
> > > [ 26.844386] rpc_execute+0x133/0x160 [sunrpc]
> > > [ 26.844401] rpc_run_task+0x103/0x160 [sunrpc]
> > > [ 26.844419] nfs4_call_sync_sequence+0x74/0xb0 [nfsv4]
> > > [ 26.844440] _nfs4_proc_readdir+0x28d/0x310 [nfsv4]
> > > [ 26.844459] nfs4_proc_readdir+0x60/0xf0 [nfsv4]
> > > [ 26.844475] nfs_readdir_xdr_to_array+0x1fb/0x410 [nfs]
> > > [ 26.844494] nfs_readdir+0x2ed/0xf00 [nfs]
> > > [ 26.844506] iterate_dir+0xaa/0x270
> >
> > Hi Trond, Anna -
> >
> > NFSv4 READDIR is hitting an XDR overflow because the XDR stream's
> > scratch buffer is missing, and one of the READDIR response's fields
> > crosses a page boundary in the receive buffer.
> >
> > Shouldn't the client's readdir XDR decoder have a scratch buffer?
>
> No it shouldn't.
>
> The READDIR XDR decoder doesn't interpret the contents of the readdir
> buffer. What it is supposed to do is read the op header and the readdir
> verifier, and then to align the remaining data into the pages that were
> allocated as buffer using a call to xdr_read_page(). Essentially, it's
> the exact same procedure as we follow for a READ call.
>
> So if we're crossing into the pages before we hit the call to
> xdr_read_pages() then that means we've allocated too small a header
> buffer. Since it only appears to happen with RPCSEC_GSS, then my money
> would be on AUTH_GSS not padding the reply buffer sufficiently when
> setting the value of auth->au_cslack.
If replies are the problem, why wouldn't we want to focus on
auth->au_rslack and auth->au_ralign?
FWIW I have both Debian Trixie and Sid/Forky VMs, and krb5{,i,p} is
working across the board for me. Normally I just use a plain MIT KDC,
so I tried IPA and that works fine too. Looking Tyler's tracepoint
output, these two jump out:
ls-969 [003] ..... 270.326933: rpc_buf_alloc: task:00000008@00000005 callsize=3932 recvsize=176 status=0
^^^
ls-969 [003] ..... 270.326936: rpc_xdr_reply_pages: task:00000008@00000005 head=[0xffff8895c29fef64,140] page=4008(88) tail=[0xffff8895c29feff0,36] len=0
^^^
Contrast that with what I see on my own systems:
ls-13558 [000] ..... 419637.290876: rpc_buf_alloc: task:00000008@00000007 callsize=3932 recvsize=148 status=0
^^^
ls-13558 [000] ..... 419637.290879: rpc_xdr_reply_pages: task:00000008@00000007 head=[0000000050ca7092,144] page=4008(88) tail=[000000007b84934f,4] len=0
^^^
Those values for the receive size and the head iov length are consistent
across all my VMs (not just my Debian ones).
>
> --
> Trond Myklebust
> Linux NFS client maintainer, Hammerspace
> trondmy@kernel.org, trond.myklebust@hammerspace.com
>
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-18 05:20 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LSlm9-dNuJ-3@gated-at.bofh.it> |
| In reply to | #90116 |
On 11/17/25 3:54 PM, Scott Mayhew wrote:
> FWIW I have both Debian Trixie and Sid/Forky VMs, and krb5{,i,p} is
> working across the board for me. Normally I just use a plain MIT KDC,
> so I tried IPA and that works fine too.
Did you confirm the enctype used?
My repro steps, from initial mounted state:
kinit
kvno -e aes256-cts-hmac-sha384-192 <nfs spn>
ls /mnt/example
On my Debian Sid VM, if I do kinit and then immediately ls, the issue
does not occur. klist shows the acquired service ticket has an
aes256-cts-hmac-sha1-96 session key.
TWR
[toc] | [prev] | [next] | [standalone]
| From | Scott Mayhew <smayhew@redhat.com> |
|---|---|
| Date | 2025-11-18 19:00 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LSy9I-dW90-13@gated-at.bofh.it> |
| In reply to | #90120 |
On Tue, 18 Nov 2025, Tyler W. Ross wrote:
> On 11/17/25 3:54 PM, Scott Mayhew wrote:
> > FWIW I have both Debian Trixie and Sid/Forky VMs, and krb5{,i,p} is
> > working across the board for me. Normally I just use a plain MIT KDC,
> > so I tried IPA and that works fine too.
>
> Did you confirm the enctype used?
Yes. This is how I was testing:
root@forky:~# uname -r
6.17.7+deb14+1-amd64
root@forky:~# systemctl restart rpc-gssd
root@forky:~# klist -ce /tmp/krb5ccmachine_SMAYHEW.TEST
klist: No credentials cache found (filename: /tmp/krb5ccmachine_SMAYHEW.TEST)
root@forky:~# for serv in forky trixie rawhide rhel10 rhel9; do for flav in krb5 krb5i krb5p; do mount -o v4.2,sec=$flav $serv.smayhew.test:/export /mnt/t; ls -lR /mnt/t >/dev/null; umount /mnt/t; done; done
root@forky:~# klist -ce /tmp/krb5ccmachine_SMAYHEW.TEST
Ticket cache: FILE:/tmp/krb5ccmachine_SMAYHEW.TEST
Default principal: nfs/forky.smayhew.test@SMAYHEW.TEST
Valid starting Expires Service principal
11/14/25 14:53:03 11/15/25 14:53:03 krbtgt/SMAYHEW.TEST@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha384-192, aes256-cts-hmac-sha384-192
11/14/25 14:53:03 11/15/25 14:53:03 nfs/forky.smayhew.test@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha384-192, aes256-cts-hmac-sha384-192
11/14/25 14:53:03 11/15/25 14:53:03 nfs/trixie.smayhew.test@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha384-192, aes256-cts-hmac-sha384-192
11/14/25 14:53:03 11/15/25 14:53:03 nfs/rawhide.smayhew.test@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha384-192, aes256-cts-hmac-sha384-192
11/14/25 14:53:04 11/15/25 14:53:03 nfs/rhel10.smayhew.test@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha384-192, aes256-cts-hmac-sha384-192
11/14/25 14:53:05 11/15/25 14:53:03 nfs/rhel9.smayhew.test@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha384-192, aes256-cts-hmac-sha384-192
>
> My repro steps, from initial mounted state:
> kinit
> kvno -e aes256-cts-hmac-sha384-192 <nfs spn>
> ls /mnt/example
>
> On my Debian Sid VM, if I do kinit and then immediately ls, the issue
> does not occur. klist shows the acquired service ticket has an
> aes256-cts-hmac-sha1-96 session key.
Oh! I see the problem. If the automatically acquired service ticket
for a normal user is using aes256-cts-hmac-sha1-96, then I'm assuming
the machine credential is also using aes256-cts-hmac-sha1-96.
Run 'klist -ce /tmp/krb5ccmachine_IPA.TWRLAB.NET' to check. You can't
use 'kvno -e' to choose a different encryption type. Why are you doing
that? Is it because you want to use the stronger encryption types? In
that case, the proper way to do this would be to manually add this line
to the "[libdefaults]" stanza of your /etc/krb5.conf:
permitted_enctypes = aes256-cts-hmac-sha384-192 aes128-cts-hmac-sha256-128 aes256-cts-hmac-sha1-96 aes128-cts-hmac-sha1-96
and get rid of allowed-enctypes settings that you may have added to
/etc/nfs.conf. Then unmount, run 'systemctl restart rpc-gssd', remount,
etc. and your system should be using aes256-cts-hmac-sha384-192 by default.
RHEL/CentOS/Fedora all ship a package called "crypto-policies" that
include system-wide configurations for various crypto packages. For
kerberos, it drops a config snippet in /etc/krb5.conf.d similar to what
I have above. AFAICT Suse has this package too, but it appears Debian
does not.
Without the permitted_enctypes setting, the kerberos library will fall
back to the default settings, which according to krb5.conf(5)
---8<---
permitted_enctypes
Identifies the encryption types that servers will permit for ses‐
sion keys and for ticket and authenticator encryption, ordered by
preference from highest to lowest. Starting in release 1.18,
this tag also acts as the default value for default_tgs_enctypes
and default_tkt_enctypes. The default value for this tag is
aes256-cts-hmac-sha1-96 aes128-cts-hmac-sha1-96
aes256-cts-hmac-sha384-192 aes128-cts-hmac-sha256-128
des3-cbc-sha1 arcfour-hmac-md5 camellia256-cts-cmac camel‐
lia128-cts-cmac.
---8<---
If I remove that line from my krb5.conf and use 'kvno -e' like your
test, then I can reproduce the behavior you're seeing:
root@forky:~# systemctl restart rpc-gssd
root@forky:~# mount -o v4.2,sec=krb5 trixie.smayhew.test:/export /mnt/t
root@forky:~# klist -ce /tmp/krb5ccmachine_SMAYHEW.TEST
Ticket cache: FILE:/tmp/krb5ccmachine_SMAYHEW.TEST
Default principal: nfs/forky.smayhew.test@SMAYHEW.TEST
Valid starting Expires Service principal
11/18/25 17:41:29 11/19/25 17:15:04 krbtgt/SMAYHEW.TEST@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha1-96, camellia256-cts-cmac
11/18/25 17:41:29 11/19/25 17:15:04 nfs/trixie.smayhew.test@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha1-96, aes256-cts-hmac-sha384-192
root@forky:~# su - smayhew
smayhew@forky:~$ kinit
Password for smayhew@SMAYHEW.TEST:
smayhew@forky:~$ kvno -e aes256-cts-hmac-sha384-192 nfs/trixie.smayhew.test
nfs/trixie.smayhew.test@SMAYHEW.TEST: kvno = 1
smayhew@forky:~$ klist -ce
Ticket cache: KEYRING:persistent:1052000003:1052000003
Default principal: smayhew@SMAYHEW.TEST
Valid starting Expires Service principal
11/18/25 17:41:53 11/19/25 17:20:27 nfs/trixie.smayhew.test@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha384-192, aes256-cts-hmac-sha384-192
11/18/25 17:41:39 11/19/25 17:20:27 krbtgt/SMAYHEW.TEST@SMAYHEW.TEST
Etype (skey, tkt): aes256-cts-hmac-sha1-96, camellia256-cts-cmac
smayhew@forky:~$ ls /mnt/t
ls: reading directory '/mnt/t': Input/output error
smayhew@forky:~$
logout
root@forky:~# grep overflow /sys/kernel/debug/tracing/trace
ls-2032 [002] ..... 3025.593816: rpc_xdr_overflow: task:00000009@00000006 nfsv4 READDIR requested=8 p=00000000dfba8950 end=00000000b97e329e xdr=[00000000389cc91a,132]/4008/[00000000b97e329e,4]/988
-Scott
>
>
> TWR
>
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-19 00:50 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LSDCp-dZRt-1@gated-at.bofh.it> |
| In reply to | #90130 |
On 11/18/25 10:52 AM, Scott Mayhew wrote:
> Oh! I see the problem. If the automatically acquired service ticket
> for a normal user is using aes256-cts-hmac-sha1-96, then I'm assuming
> the machine credential is also using aes256-cts-hmac-sha1-96.
> Run 'klist -ce /tmp/krb5ccmachine_IPA.TWRLAB.NET' to check. You can't
> use 'kvno -e' to choose a different encryption type. Why are you doing
> that?
Aha! Thank you!
That's exactly the case: the machine credential is
aes256-cts-hmac-sha1-96.
So, taking a step back for context/background: this issue was escalated
to me by someone attempting to use constrained delegation via gssproxy.
In the course of troubleshooting that, we found (by examining the
krb5kdc logs on the IPA server) that the NFS service ticket acquired by
gssproxy had an aes256-cts-hmac-sha384-192 session key.
Not understanding that the machine and user tickets must having matching
enctypes, I ended up down this rabbit hole thinking the problem was with
the SHA2 enctypes. Sorry to bring you all with me on that misadventure.
The actual issue at hand then seems to be that gssproxy is requesting
(and receiving) a service ticket with an unusable (for the NFS mount)
enctype, when performing constrained delegation/S4U2Proxy.
krb5kdc logs of gssproxy performing S4U2Self and S4U2Proxy:Nov 18
18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info): TGS_REQ (8 etypes
{aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17),
aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19),
UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23),
camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 10.108.2.105:
ISSUE: authtime 1763506600, etypes {rep=aes256-cts-hmac-sha1-96(18),
tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha1-96(18)},
host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET for
host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info): ...
PROTOCOL-TRANSITION s4u-client=jsmith@IPA.TWRLAB.NET
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info): closing
down fd 4
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): TGS_REQ (4
etypes {aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19),
aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 10.108.2.105:
ISSUE: authtime 1763506600, etypes {rep=aes256-cts-hmac-sha1-96(18),
tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha384-192(20)},
host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET for
nfs/nfssrv.ipa.twrlab.net@IPA.TWRLAB.NET
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): ...
CONSTRAINED-DELEGATION s4u-client=jsmith@IPA.TWRLAB.NET
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): closing
down fd 11
On the Fedora 43 client, gssproxy also acquires an
aes256-cts-hmac-sha384-192 service ticket, but the machine credential is
aes256-cts-hmac-sha384-192 and everything works as-expected.
TWR
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-17 19:50 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LScsy-dH2y-7@gated-at.bofh.it> |
| In reply to | #90004 |
On Monday, November 17th, 2025 at 6:41 AM, Chuck Lever <chuck.lever@oracle.com> wrote: > > Is this gssd mishandling some setup/initialization? > > Or is there a miscalculation happening somewhere further up? > > Does Debian's user space Kerberos support the sha2 enctypes? Appears to. MIT Kerberos docs list sha2 enctypes support on releases >=1.15 . Debian 13 and Fedora 43 are both shipping 1.21.3 . Debian unstable currently has 1.22.1 . I haven't had any issues managing sha2 keytabs, tickets, etc. with the userspace tools. And at least some NFS operations other than READDIR do seem to work, though I haven't tested that beyond observing cat, stat, and touch are functional. TWR
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-18 05:40 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LSlFv-dNBE-1@gated-at.bofh.it> |
| In reply to | #90004 |
On 11/17/25 4:05 PM, Scott Mayhew wrote: > On Mon, 17 Nov 2025, Tyler W. Ross wrote: > >> Weird behavior I just discovered: >> >> Explicitly setting allowed-enctypes in the gssd section of /etc/nfs.conf >> to exclude aes256-cts-hmac-sha1-96 makes both SHA2 ciphers work as >> expected (assuming each is allowed). >> >> If allowed-enctypes is unset (letting gssd interrogate the kernel for >> supported enctypes) or includes aes256-cts-hmac-sha1-96, then the XDR >> overflow occurs. >> >> Non-working configurations (first is the commented-out default in nfs.conf): >> allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128,camellia256-cts-cmac,camellia128-cts-cmac,aes256-cts-hmac-sha1-96,aes128-cts-hmac-sha1-96 >> allowed-enctypes=aes256-cts-hmac-sha384-192,aes256-cts-hmac-sha1-96 >> allowed-enctypes=aes128-cts-hmac-sha256-128,aes256-cts-hmac-sha1-96 >> allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128,aes256-cts-hmac-sha1-96 >> >> Working configurations (first is default sans aes256-cts-hmac-sha1-96): >> allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128,camellia256-cts-cmac,camellia128-cts-cmac,aes128-cts-hmac-sha1-96 >> allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha256-128 >> allowed-enctypes=aes256-cts-hmac-sha384-192,aes128-cts-hmac-sha1-96 >> allowed-enctypes=aes128-cts-hmac-sha256-128,aes128-cts-hmac-sha1-96 >> > > That doesn't really make sense. You should only need to use the > allowed-enctypes setting if you're talking to an NFS server that doesn't > have support for the new encryption types. > > It basically works like the "permitted_enctypes" option in krb5.conf, > except it only affects NFS rather than affecting your krb5 configuration > as a whole. Agreed. It really doesn't make sense. It may just be me being confounded by some ancillary behavior I don't understand. I find it especially strange that allowed-enctypes=aes256-cts-hmac-sha384-192 works, but unset allowed-enctypes with a manually acquired aes256-cts-hmac-sha384-192 ticket doesn't work. allowed-enctypes=aes256-cts-hmac-sha384-192 works both with an automatically acquired service ticket (kinit then ls) and a manually acquired service ticket (via kvno -e). > Can you go back and re-do the tracepoint capture, except this time > umount your NFS filessytems before starting the capture (i.e. perform > the mount command while trace-cmd is running). I'm curious what values > the rpcgss_update_slack tracepoint shows. Here are the 2 rpcgss_update_slack occurrences, with a couple lines of context. Let me know if you'd like the full report: it's ~1300 lines. mount.nfs4-1043 [005] ..... 190.746932: rpc_task_run_action: task:00000002@00000001 flags=DYNAMIC|NO_ROUND_ROBIN|SOFT|SENT|TIMEOUT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status mount.nfs4-1043 [005] ..... 190.746932: rpc_task_run_action: task:00000002@00000001 flags=DYNAMIC|NO_ROUND_ROBIN|SOFT|SENT|TIMEOUT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_decode mount.nfs4-1043 [005] ..... 190.746933: rpc_xdr_recvfrom: task:00000002@00000001 head=[0xffff8a61a2848fd4,4392] page=0(0) tail=[(nil),0] len=312 mount.nfs4-1043 [005] ..... 190.746938: rpcgss_update_slack: task:00000002@00000001 xid=0xb28269cc auth=0xffff8a6189400798 rslack=19 ralign=11 verfsize=9 mount.nfs4-1043 [005] ..... 190.746939: rpc_task_run_action: task:00000002@00000001 flags=DYNAMIC|NO_ROUND_ROBIN|SOFT|SENT|TIMEOUT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task mount.nfs4-1043 [005] ..... 190.746939: rpc_task_end: task:00000002@00000001 flags=DYNAMIC|NO_ROUND_ROBIN|SOFT|SENT|TIMEOUT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task mount.nfs4-1043 [005] ..... 190.746940: rpc_stats_latency: task:00000002@00000001 xid=0xb28269cc nfsv4 EXCHANGE_ID backlog=12836 rtt=136 execute=12995 xprt_id=1 -- mount.nfs4-1043 [002] ..... 190.755687: rpc_task_run_action: task:00000001@00000002 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status mount.nfs4-1043 [002] ..... 190.755687: rpc_task_run_action: task:00000001@00000002 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_decode mount.nfs4-1043 [002] ..... 190.755688: rpc_xdr_recvfrom: task:00000001@00000002 head=[0xffff8a6182b4e6ac,2920] page=0(0) tail=[(nil),0] len=192 mount.nfs4-1043 [002] ..... 190.755691: rpcgss_update_slack: task:00000001@00000002 xid=0xb68269cc auth=0xffff8a6187759498 rslack=9 ralign=9 verfsize=9 mount.nfs4-1043 [002] ..... 190.755694: rpc_task_run_action: task:00000001@00000002 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task mount.nfs4-1043 [002] ..... 190.755694: rpc_task_end: task:00000001@00000002 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task mount.nfs4-1043 [002] ..... 190.755694: rpc_stats_latency: task:00000001@00000002 xid=0xb68269cc nfsv4 LOOKUP_ROOT backlog=7101 rtt=91 execute=7218 xprt_id=1 And here's with allowed-enctypes=aes256-cts-hmac-sha384-192 mount.nfs4-1100 [005] ..... 580.221598: rpc_task_run_action: task:00000002@00000001 flags=DYNAMIC|NO_ROUND_ROBIN|SOFT|SENT|TIMEOUT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status mount.nfs4-1100 [005] ..... 580.221598: rpc_task_run_action: task:00000002@00000001 flags=DYNAMIC|NO_ROUND_ROBIN|SOFT|SENT|TIMEOUT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_decode mount.nfs4-1100 [005] ..... 580.221598: rpc_xdr_recvfrom: task:00000002@00000001 head=[0xffff8b2b98850fd4,4392] page=0(0) tail=[(nil),0] len=336 mount.nfs4-1100 [005] ..... 580.221604: rpcgss_update_slack: task:00000002@00000001 xid=0x4c050148 auth=0xffff8b2b88864818 rslack=25 ralign=14 verfsize=12 mount.nfs4-1100 [005] ..... 580.221605: rpc_task_run_action: task:00000002@00000001 flags=DYNAMIC|NO_ROUND_ROBIN|SOFT|SENT|TIMEOUT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task mount.nfs4-1100 [005] ..... 580.221606: rpc_task_end: task:00000002@00000001 flags=DYNAMIC|NO_ROUND_ROBIN|SOFT|SENT|TIMEOUT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task mount.nfs4-1100 [005] ..... 580.221607: rpc_stats_latency: task:00000002@00000001 xid=0x4c050148 nfsv4 EXCHANGE_ID backlog=13249 rtt=164 execute=13435 xprt_id=1 -- mount.nfs4-1100 [000] ..... 580.230841: rpc_task_run_action: task:00000001@00000002 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_status mount.nfs4-1100 [000] ..... 580.230841: rpc_task_run_action: task:00000001@00000002 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=call_decode mount.nfs4-1100 [000] ..... 580.230841: rpc_xdr_recvfrom: task:00000001@00000002 head=[0xffff8b2ba07b66ac,2920] page=0(0) tail=[(nil),0] len=204 mount.nfs4-1100 [000] ..... 580.230845: rpcgss_update_slack: task:00000001@00000002 xid=0x50050148 auth=0xffff8b2b88864b18 rslack=12 ralign=12 verfsize=12 mount.nfs4-1100 [000] ..... 580.230847: rpc_task_run_action: task:00000001@00000002 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task mount.nfs4-1100 [000] ..... 580.230847: rpc_task_end: task:00000001@00000002 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF runstate=RUNNING|0x4 status=0 action=rpc_exit_task mount.nfs4-1100 [000] ..... 580.230848: rpc_stats_latency: task:00000001@00000002 xid=0x50050148 nfsv4 LOOKUP_ROOT backlog=7760 rtt=98 execute=7878 xprt_id=1 TWR
[toc] | [prev] | [next] | [standalone]
| From | Scott Mayhew <smayhew@redhat.com> |
|---|---|
| Date | 2025-11-19 14:40 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LSQzE-e8GL-17@gated-at.bofh.it> |
| In reply to | #90004 |
On Wed, 19 Nov 2025, Salvatore Bonaccorso wrote:
> Hi,
>
> On Tue, Nov 18, 2025 at 11:43:29PM +0000, Tyler W. Ross wrote:
> > On 11/18/25 10:52 AM, Scott Mayhew wrote:
> > > Oh! I see the problem. If the automatically acquired service ticket
> > > for a normal user is using aes256-cts-hmac-sha1-96, then I'm assuming
> > > the machine credential is also using aes256-cts-hmac-sha1-96.
> > > Run 'klist -ce /tmp/krb5ccmachine_IPA.TWRLAB.NET' to check. You can't
> > > use 'kvno -e' to choose a different encryption type. Why are you doing
> > > that?
> >
> > Aha! Thank you!
>
> Thanks to all helping to debug this issue when reported downstream in
> Debian, your time invested is very much appreciated!
While I still assert that if you want to use the stronger encryption
types with NFS, then you should prioritize those encryption types higher
in your kerberos configuration... after discussing this yesterday with
Olga I think the above scenario should probably work too.
I just sent a patch that makes that happen, but I forgot to add
"--in-reply-to" my "git send-email" command, so here's the link:
https://lore.kernel.org/linux-nfs/20251119133231.3660975-1-smayhew@redhat.com/T/#u
-Scott
>
> > That's exactly the case: the machine credential is
> > aes256-cts-hmac-sha1-96.
> >
> > So, taking a step back for context/background: this issue was escalated to
> > me by someone attempting to use constrained delegation via gssproxy. In the
> > course of troubleshooting that, we found (by examining the krb5kdc logs on
> > the IPA server) that the NFS service ticket acquired by gssproxy had an
> > aes256-cts-hmac-sha384-192 session key.
> >
> > Not understanding that the machine and user tickets must having matching
> > enctypes, I ended up down this rabbit hole thinking the problem
> > was with the SHA2 enctypes. Sorry to bring you all with me on that
> > misadventure.
> >
> >
> >
> > The actual issue at hand then seems to be that gssproxy is requesting (and
> > receiving) a service ticket with an unusable (for the NFS mount) enctype,
> > when performing constrained delegation/S4U2Proxy.
> >
> > krb5kdc logs of gssproxy performing S4U2Self and S4U2Proxy:Nov 18 18:06:51
> > directory.ipa.twrlab.net krb5kdc[8463](info): TGS_REQ (8 etypes
> > {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17),
> > aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19),
> > UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23),
> > camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 10.108.2.105: ISSUE:
> > authtime 1763506600, etypes {rep=aes256-cts-hmac-sha1-96(18),
> > tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha1-96(18)},
> > host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET for
> > host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET
> > Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info):
> > ... PROTOCOL-TRANSITION s4u-client=jsmith@IPA.TWRLAB.NET
> > Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info): closing down
> > fd 4
> > Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): TGS_REQ (4
> > etypes {aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19),
> > aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 10.108.2.105:
> > ISSUE: authtime 1763506600, etypes {rep=aes256-cts-hmac-sha1-96(18),
> > tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha384-192(20)},
> > host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET for
> > nfs/nfssrv.ipa.twrlab.net@IPA.TWRLAB.NET
> > Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): ...
> > CONSTRAINED-DELEGATION s4u-client=jsmith@IPA.TWRLAB.NET
> > Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): closing down
> > fd 11
> >
> >
> > On the Fedora 43 client, gssproxy also acquires an
> > aes256-cts-hmac-sha384-192 service ticket, but the machine credential is
> > aes256-cts-hmac-sha384-192 and everything works as-ex
> > pected.
>
> I'm looping in here the gssproxy maintainer as well. Simon, this is
> about https://bugs.debian.org/1120598 . I assume there is nothing on
> gssroxy side which can be done to warn about the situation, quoting
> again:
>
> > The actual issue at hand then seems to be that gssproxy is requesting (and
> > receiving) a service ticket with an unusable (for the NFS mount) enctype,
> > when performing constrained delegation/S4U2Proxy.
>
> ?
>
> Regards,
> Salvatore
>
[toc] | [prev] | [next] | [standalone]
| From | "Tyler W. Ross" <TWR@tylerwross.com> |
|---|---|
| Date | 2025-11-19 18:30 +0100 |
| Subject | Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2 |
| Message-ID | <LSUad-ebfP-7@gated-at.bofh.it> |
| In reply to | #90004 |
On 11/19/25 6:36 AM, Scott Mayhew wrote:
> While I still assert that if you want to use the stronger encryption
> types with NFS, then you should prioritize those encryption types higher
> in your kerberos configuration... after discussing this yesterday with
> Olga I think the above scenario should probably work too.
There was no intent or attempt to specify encryption types in the
original configuration. Fiddling with enctypes only came up in the
course of troubleshooting.
This issue was found/replicated by:
1. Configuring a stock Debian 13 client using ipa-client-install against
a freshly deployed Fedora 43 IPA instance.
2. Adding a krb5 NFS entry in fstab
3. Installing and enabling gssproxy (use-gss-proxy=1 in nfs.conf)
4. Configuring gssproxy for constrained delegation as described in the
docs:
[service/nfs-client]
mechs = krb5
cred_store = keytab:/etc/krb5.keytab
cred_store = ccache:FILE:/var/lib/gssproxy/clients/krb5cc_%U
cred_usage = initiate
allow_any_uid = yes
impersonate = true
euid = 0
5. Allowing constrained delegation on the IPA/KDC side
I think this should be a working configuration: it shouldn't be
necessary to change the enctypes from default for this to work.
But the above results in the aes256-cts-hmac-sha1-96 machine credential
and aes256-cts-hmac-sha384-192 client ticket situation.
> I just sent a patch that makes that happen, but I forgot to add
> "--in-reply-to" my "git send-email" command, so here's the link:
>
> https://lore.kernel.org/linux-nfs/20251119133231.3660975-1-smayhew@redhat.com/T/#u
Thanks, Scott.
So it's technically possible for the machine and client credentials to
have mismatched enctypes? There are just assumptions (like the slack
variable calculations) that need to be changed to support that?
I'm also wondering if the gssproxy behavior is correct. I obviously
don't understand all the nuance here, but it appears gssproxy is
requesting the service ticket with a different preference/order of
enctypes -- which leads to this mismatch situation.
Looking at the KDC logs (below), the protocol transition request has
enctypes matching the default permitted_enctypes described in
krb5.conf(5) (i.e., with aes256-cts-hmac-sha1-96 first). But then the
constrained delegation request lists aes256-cts-hmac-sha384-192 first,
which I assume indicates preference and is why that enctype is issued.
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info): TGS_REQ (8 etypes {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17), aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23), camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 10.108.2.105: ISSUE: authtime 1763506600, etypes {rep=aes256-cts-hmac-sha1-96(18), tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha1-96(18)}, host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET for host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info): ... PROTOCOL-TRANSITION s4u-client=jsmith@IPA.TWRLAB.NET
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info): closing down fd 4
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): TGS_REQ (4 etypes {aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 10.108.2.105: ISSUE: authtime 1763506600, etypes {rep=aes256-cts-hmac-sha1-96(18), tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha384-192(20)}, host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET for nfs/nfssrv.ipa.twrlab.net@IPA.TWRLAB.NET
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): ... CONSTRAINED-DELEGATION s4u-client=jsmith@IPA.TWRLAB.NET
Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): closing down fd 11
>
> -Scott
>
>>
>>> That's exactly the case: the machine credential is
>>> aes256-cts-hmac-sha1-96.
>>>
>>> So, taking a step back for context/background: this issue was escalated to
>>> me by someone attempting to use constrained delegation via gssproxy. In the
>>> course of troubleshooting that, we found (by examining the krb5kdc logs on
>>> the IPA server) that the NFS service ticket acquired by gssproxy had an
>>> aes256-cts-hmac-sha384-192 session key.
>>>
>>> Not understanding that the machine and user tickets must having matching
>>> enctypes, I ended up down this rabbit hole thinking the problem
>>> was with the SHA2 enctypes. Sorry to bring you all with me on that
>>> misadventure.
>>>
>>>
>>>
>>> The actual issue at hand then seems to be that gssproxy is requesting (and
>>> receiving) a service ticket with an unusable (for the NFS mount) enctype,
>>> when performing constrained delegation/S4U2Proxy.
>>>
>>> krb5kdc logs of gssproxy performing S4U2Self and S4U2Proxy:Nov 18 18:06:51
>>> directory.ipa.twrlab.net krb5kdc[8463](info): TGS_REQ (8 etypes
>>> {aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17),
>>> aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19),
>>> UNSUPPORTED:des3-hmac-sha1(16), DEPRECATED:arcfour-hmac(23),
>>> camellia128-cts-cmac(25), camellia256-cts-cmac(26)}) 10.108.2.105: ISSUE:
>>> authtime 1763506600, etypes {rep=aes256-cts-hmac-sha1-96(18),
>>> tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha1-96(18)},
>>> host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET for
>>> host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET
>>> Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info):
>>> ... PROTOCOL-TRANSITION s4u-client=jsmith@IPA.TWRLAB.NET
>>> Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8463](info): closing down
>>> fd 4
>>> Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): TGS_REQ (4
>>> etypes {aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19),
>>> aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 10.108.2.105:
>>> ISSUE: authtime 1763506600, etypes {rep=aes256-cts-hmac-sha1-96(18),
>>> tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha384-192(20)},
>>> host/nfsclient.ipa.twrlab.net@IPA.TWRLAB.NET for
>>> nfs/nfssrv.ipa.twrlab.net@IPA.TWRLAB.NET
>>> Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): ...
>>> CONSTRAINED-DELEGATION s4u-client=jsmith@IPA.TWRLAB.NET
>>> Nov 18 18:06:51 directory.ipa.twrlab.net krb5kdc[8465](info): closing down
>>> fd 11
>>>
>>>
>>> On the Fedora 43 client, gssproxy also acquires an
>>> aes256-cts-hmac-sha384-192 service ticket, but the machine credential is
>>> aes256-cts-hmac-sha384-192 and everything works as-ex
>>> pected.
>>
>> I'm looping in here the gssproxy maintainer as well. Simon, this is
>> about https://bugs.debian.org/1120598 . I assume there is nothing on
>> gssroxy side which can be done to warn about the situation, quoting
>> again:
>>
>>> The actual issue at hand then seems to be that gssproxy is requesting (and
>>> receiving) a service ticket with an unusable (for the NFS mount) enctype,
>>> when performing constrained delegation/S4U2Proxy.
>>
>> ?
>>
>> Regards,
>> Salvatore
>>
>
TWR
[toc] | [prev] | [next] | [standalone]
| From | "Debian Bug Tracking System" <owner@bugs.debian.org> |
|---|---|
| Date | 2026-03-09 22:10 +0100 |
| Subject | Bug#1120598: marked as done (nfs: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2) |
| Message-ID | <MwQ1s-6fFX-19@gated-at.bofh.it> |
| In reply to | #90004 |
[Multipart message — attachments visible in raw view] — view raw
Your message dated Mon, 09 Mar 2026 21:06:16 +0000
with message-id <E1vzhns-0000000D33m-00B8@fasolo.debian.org>
and subject line Bug#1120598: fixed in nfs-utils 1:2.8.6-1
has caused the Debian Bug report #1120598,
regarding nfs: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2
to be marked as done.
This means that you claim that the problem has been dealt with.
If this is not the case it is now your responsibility to reopen the
Bug report if necessary, and/or fix the problem forthwith.
(NB: If you are a system administrator and have no idea what this
message is talking about, this may indicate a serious mail system
misconfiguration somewhere. Please contact owner@bugs.debian.org
immediately.)
--
1120598: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1120598
Debian Bug Tracking System
Contact owner@bugs.debian.org with problems
[toc] | [prev] | [standalone]
Back to top | Article view | linux.debian.kernel
csiph-web