Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.debian.bugs.dist > #1270038 > unrolled thread

Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2

Started by"Tyler W. Ross" <TWR@tylerwross.com>
First post2025-11-13 18:20 +0100
Last post2025-11-19 14:40 +0100
Articles 15 — 3 participants

Back to article view | Back to linux.debian.bugs.dist

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  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 "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 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 Scott Mayhew <smayhew@redhat.com> - 2025-11-19 14:40 +0100

#1270038 — Bug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-13 18:20 +0100
SubjectBug#1120598: ls input/output error ("NFS: readdir(/) returns -5") on krb5 NFSv4 client using SHA2
Message-ID<LQJ9g-cHSX-3@gated-at.bofh.it>
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] | [next] | [standalone]

#1270042

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-13 19:10 +0100
Message-ID<LQJVD-cIsP-1@gated-at.bofh.it>
In reply to#1270038
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]

#1270055

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-13 20:00 +0100
Message-ID<LQKI1-cIMi-5@gated-at.bofh.it>
In reply to#1270042
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]

#1270097

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-14 05:40 +0100
Message-ID<LQTLj-cP9F-1@gated-at.bofh.it>
In reply to#1270038
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]

#1270100

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-14 06:20 +0100
Message-ID<LQUo1-cPF1-3@gated-at.bofh.it>
In reply to#1270097
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]

#1270330

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-16 01:50 +0100
Message-ID<LRz7P-dhgS-1@gated-at.bofh.it>
In reply to#1270100
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]

#1270426

FromTrond Myklebust <trondmy@kernel.org>
Date2025-11-16 19:30 +0100
Message-ID<LRPFD-ds93-1@gated-at.bofh.it>
In reply to#1270330
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]

#1270469

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-17 06:30 +0100
Message-ID<LRZYl-dz0H-1@gated-at.bofh.it>
In reply to#1270426
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]

#1270538

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-17 19:50 +0100
Message-ID<LScsy-dH2y-7@gated-at.bofh.it>
In reply to#1270469
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]

#1270579

FromScott Mayhew <smayhew@redhat.com>
Date2025-11-18 00:10 +0100
Message-ID<LSgw9-dK5j-9@gated-at.bofh.it>
In reply to#1270469
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]

#1270578

FromScott Mayhew <smayhew@redhat.com>
Date2025-11-18 00:10 +0100
Message-ID<LSgw9-dK5j-1@gated-at.bofh.it>
In reply to#1270426
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]

#1270602

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-18 05:20 +0100
Message-ID<LSlm9-dNuJ-3@gated-at.bofh.it>
In reply to#1270578
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]

#1270695

FromScott Mayhew <smayhew@redhat.com>
Date2025-11-18 19:00 +0100
Message-ID<LSy9I-dW90-13@gated-at.bofh.it>
In reply to#1270602
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]

#1270732

From"Tyler W. Ross" <TWR@tylerwross.com>
Date2025-11-19 00:50 +0100
Message-ID<LSDCp-dZRt-1@gated-at.bofh.it>
In reply to#1270695
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]

#1270798

FromScott Mayhew <smayhew@redhat.com>
Date2025-11-19 14:40 +0100
Message-ID<LSQzE-e8GL-17@gated-at.bofh.it>
In reply to#1270732
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] | [standalone]

Back to top | Article view | linux.debian.bugs.dist

csiph-web