Re: WARN_ONCE from nfsd_break_one_deleg

[Dai Ngo <dai.ngo@oracle.com>]

On 3/26/24 9:42 AM, Chuck Lever wrote:
>
> On 3/26/24 11:04 AM, Donald Buczek wrote:
>> Hi,
>>
>> we just got this on a nfs file server on 6.6.12 :
>>
>> [2719554.674554] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 00000000432042d3 xid c369f54d
>> [2719555.391416] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 0000000017cc0507 xid d6018727
>> [2719555.742118] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 000000008f2509ff xid 83d0248e
>> [2719555.742566] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 00000000637a135a xid 7064546d
>> [2719555.742803] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 0000000044ea3c51 xid a184bbe5
>> [2719555.742836] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 00000000b6992e65 xid ed3fe82e
>> [2719555.785358] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 0000000044ea3c51 xid a384bbe5
>> [2719588.733414] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 000000008f2509ff xid 89d0248e
>> [2719592.067221] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 00000000b6992e65 xid f33fe82e
>> [2719807.431344] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 00000000fd87f88f xid 28b51379
>> [2719838.510792] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 00000000432042d3 xid fa69f54d
>> [2719852.493779] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 00000000ac1e99fe xid a16378bb
>> [2719852.494853] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 0000000017cc0507 xid 0f028727
>> [2719852.515457] receive_cb_reply: Got unrecognized reply: calldir 
>> 0x1 xpt_bc_xprt 0000000017cc0507 xid 10028727
>
> These clients are sending NFSv4 callback replies that the server does 
> not have a waiting XID for. It's a sign of a significant communication 
> mix-up between the server and client.
>
> It would help us to get some details about your clients, the NFS 
> version in use, and how long you've been using this kernel. Also, a 
> raw packet capture might shed a little more light on the issue.

This warning has has no effect on the server operation and was remove.
See commit 05a4b58301c3.

-Dai

>
>> [2719917.753429] ------------[ cut here ]------------
>> [2719917.758951] WARNING: CPU: 1 PID: 1448 at 
>> fs/nfsd/nfs4state.c:4939 nfsd_break_deleg_cb+0x115/0x190 [nfsd]
>> [2719917.769208] Modules linked in: af_packet xt_nat xt_tcpudp 
>> iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 
>> rpcsec_gss_krb5 nfsv4 nfs i915 iosf_mbi drm_buddy drm_display_helper 
>> ttm intel_gtt video 8021q garp stp mrp llc input_leds 
>> x86_pkg_temp_thermal led_class hid_generic usbhid coretemp kvm_intel 
>> kvm irqbypass tg3 libphy smartpqi mgag200 i2c_algo_bit efi_pstore 
>> iTCO_wdt i40e crc32c_intel wmi_bmof pstore iTCO_vendor_support wmi 
>> ipmi_si nfsd auth_rpcgss oid_registry nfs_acl lockd grace sunrpc 
>> efivarfs ip_tables x_tables ipv6 autofs4
>> [2719917.818740] CPU: 1 PID: 1448 Comm: nfsd Not tainted 
>> 6.6.12.mx64.461 #1
>> [2719917.825777] Hardware name: Dell Inc. PowerEdge T440/021KCD, BIOS 
>> 2.12.2 07/09/2021
>> [2719917.833781] RIP: 0010:nfsd_break_deleg_cb+0x115/0x190 [nfsd]
>> [2719917.839911] Code: 00 00 00 e8 3d ae e8 e0 e9 5f ff ff ff 48 89 
>> df be 01 00 00 00 e8 8b 1f 3d e1 48 8d bb 98 00 00 00 e8 ef 10 01 00 
>> 84 c0 75 8a <0f> 0b eb 86 65 8b 05 0c 66 e0 5f 89 c0 48 0f a3 05 d6 
>> 1a 75 e2 0f
>> [2719917.859303] RSP: 0018:ffffc9000bae7b70 EFLAGS: 00010246
>> [2719917.864962] RAX: 0000000000000000 RBX: ffff8881e2fd6000 RCX: 
>> 0000000000000024
>> [2719917.872520] RDX: ffff8881e2fd60c8 RSI: ffff889086d5de00 RDI: 
>> 0000000000000200
>> [2719917.880050] RBP: ffff889301aa812c R08: 0000000000033580 R09: 
>> 0000000000000000
>> [2719917.887575] R10: ffff889ef63b20d8 R11: 0000000000000000 R12: 
>> ffff888104cfb290
>> [2719917.895095] R13: ffff889301aa8118 R14: ffff88989c8ace00 R15: 
>> ffff888104cfb290
>> [2719917.902625] FS:  0000000000000000(0000) 
>> GS:ffff88a03fc00000(0000) knlGS:0000000000000000
>> [2719917.911094] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [2719917.917236] CR2: 00007fb8a1cfc418 CR3: 000000000262c006 CR4: 
>> 00000000007706e0
>> [2719917.924760] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 
>> 0000000000000000
>> [2719917.932285] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 
>> 0000000000000400
>> [2719917.939833] PKRU: 55555554
>> [2719917.942971] Call Trace:
>> [2719917.945834]  <TASK>
>> [2719917.948344]  ? __warn+0x81/0x140
>> [2719917.951983]  ? nfsd_break_deleg_cb+0x115/0x190 [nfsd]
>> [2719917.957470]  ? report_bug+0x171/0x1a0
>> [2719917.961562]  ? handle_bug+0x3c/0x70
>> [2719917.965459]  ? exc_invalid_op+0x17/0x70
>> [2719917.969715]  ? asm_exc_invalid_op+0x1a/0x20
>> [2719917.974317]  ? nfsd_break_deleg_cb+0x115/0x190 [nfsd]
>> [2719917.979820]  __break_lease+0x24b/0x7c0
>> [2719917.983991]  ? __pfx_nfsd_acceptable+0x10/0x10 [nfsd]
>> [2719917.989495]  nfs4_get_vfs_file+0x195/0x380 [nfsd]
>> [2719917.994740]  ? prepare_creds+0x14c/0x240
>> [2719917.999164]  nfsd4_process_open2+0x3ed/0x16b0 [nfsd]
>> [2719918.004570]  ? nfsd_permission+0x4e/0x100 [nfsd]
>> [2719918.009618]  ? fh_verify+0x17b/0x8a0 [nfsd]
>> [2719918.014243]  nfsd4_open+0x6ae/0xcd0 [nfsd]
>> [2719918.018777]  ? nfsd4_encode_operation+0xa6/0x290 [nfsd]
>> [2719918.024524]  nfsd4_proc_compound+0x2f2/0x6a0 [nfsd]
>> [2719918.029922]  nfsd_dispatch+0xee/0x220 [nfsd]
>> [2719918.034619]  ? __pfx_nfsd+0x10/0x10 [nfsd]
>> [2719918.039144]  svc_process_common+0x307/0x730 [sunrpc]
>> [2719918.044551]  ? __pfx_nfsd_dispatch+0x10/0x10 [nfsd]
>> [2719918.049883]  ? __pfx_nfsd+0x10/0x10 [nfsd]
>> [2719918.054404]  svc_process+0x131/0x180 [sunrpc]
>> [2719918.059171]  nfsd+0x84/0xd0 [nfsd]
>> [2719918.063012]  kthread+0xe5/0x120
>> [2719918.066539]  ? __pfx_kthread+0x10/0x10
>> [2719918.070664]  ret_from_fork+0x31/0x50
>> [2719918.074611]  ? __pfx_kthread+0x10/0x10
>> [2719918.078735]  ret_from_fork_asm+0x1b/0x30
>> [2719918.083018]  </TASK>
>> [2719918.085563] ---[ end trace 0000000000000000 ]---
>>
>> nfsd_break_deleg_cb+0x115 is the 
>> `WARN_ON_ONCE(!nfsd4_run_cb(&dp->dl_recall))` in 
>> nfsd_break_one_deleg() in our compilation
>>
>> I think that means, that the callback is already scheduled?
>>
>> One nfs client hung trying to mount something from that server.
>>
>> Best
>>
>>    Donald
>>
>