On 1/17/25 2:43 PM, Baptiste PELLEGRIN wrote:
On 1/16/25 9:07 PM, Chuck Lever wrote:On 1/11/25 3:14 AM, Pellegrin Baptiste wrote:On 09/01/25 17:32, *Chuck Lever * <chuck.lever@xxxxxxxxxx> wrote:On 1/9/25 7:42 AM, Jeff Layton wrote: >On Thu, 2025-01-09 at 12:56 +0100, Christian Herzog wrote: >>Dear Chuck, >> >>On Wed, Jan 08, 2025 at 10:07:49AM -0500, Chuck Lever wrote: >>>On 1/8/25 9:54 AM, Christian Herzog wrote: >>>>Dear Chuck, >>>> >>>>On Wed, Jan 08, 2025 at 08:33:23AM -0500, Chuck Lever wrote: >>>>>On 1/7/25 4:17 PM, Salvatore Bonaccorso wrote: >>>>>>Hi Chuck, >>>>>> >>>>>>Thanks for your time on this, much appreciated. >>>>>> >>>>>>On Wed, Jan 01, 2025 at 02:24:50PM -0500, Chuck Lever wrote: >>>>>>>On 12/25/24 4:15 AM, Salvatore Bonaccorso wrote: >>>>>>>>Hi Chuck, hi all, >>>>>>>>>>>>>>>>[it was not ideal to pick one of the message for this followup, let me >>>>>>>>know if you want a complete new thread, adding as well Benjamin and>>>>>>>>Trond as they are involved in one mentioned patch] >>>>>>>>>>>>>>>>On Mon, Jun 17, 2024 at 02:31:54PM +0000, Chuck Lever III wrote:>>>>>>>>> >>>>>>>>>>>>>>>>>>>On Jun 17, 2024, at 2:55 AM, Harald Dunkel <harald.dunkel@xxxxxxxxxx> wrote:>>>>>>>>>> >>>>>>>>>>Hi folks, >>>>>>>>>>>>>>>>>>>>what would be the reason for nfsd getting stuck somehow and becoming>>>>>>>>>>an unkillable process? See >>>>>>>>>>>>>>>>>>>>- https://bugs.debian.org/cgi-bin/bugreport.cgi? bug=1071562 <https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1071562> >>>>>>>>>>- https://bugs.launchpad.net/ubuntu/+source/nfs-utils/ +bug/2062568 <https://bugs.launchpad.net/ubuntu/+source/nfs-utils/ +bug/2062568>>>>>>>>>>>>>>>>>>>>>Doesn't this mean that something inside the kernel gets stuck as>>>>>>>>>>well? Seems odd to me. >>>>>>>>>>>>>>>>>>I'm not familiar with the Debian or Ubuntu kernel packages. Can >>>>>>>>>the kernel release numbers be translated to LTS kernel releases >>>>>>>>>please? Need both "last known working" and "first broken" releases.>>>>>>>>> >>>>>>>>>This: >>>>>>>>>>>>>>>>>>[ 6596.911785] RPC: Could not send backchannel reply error: -110 >>>>>>>>>[ 6596.972490] RPC: Could not send backchannel reply error: -110 >>>>>>>>>[ 6837.281307] RPC: Could not send backchannel reply error: -110>>>>>>>>>>>>>>>>>>is a known set of client backchannel bugs. Knowing the LTS kernel>>>>>>>>>releases (see above) will help us figure out what needs to be >>>>>>>>>backported to the LTS kernels kernels in question. >>>>>>>>> >>>>>>>>>This: >>>>>>>>> >>>>>>>>>[11183.290619] wait_for_completion+0x88/0x150 >>>>>>>>>[11183.290623] __flush_workqueue+0x140/0x3e0 >>>>>>>>>[11183.290629] nfsd4_probe_callback_sync+0x1a/0x30 [nfsd] >>>>>>>>>[11183.290689] nfsd4_destroy_session+0x186/0x260 [nfsd] >>>>>>>>>>>>>>>>>>is probably related to the backchannel errors on the client, but>>>>>>>>>client bugs shouldn't cause the server to hang like this. We>>>>>>>>>might be able to say more if you can provide the kernel release>>>>>>>>>translations (see above). >>>>>>>>>>>>>>>>In Debian we hstill have the bug #1071562 open and one person notified >>>>>>>>mye offlist that it appears that the issue get more frequent since >>>>>>>>they updated on NFS client side from Ubuntu 20.04 to Debian bookworm>>>>>>>>with a 6.1.y based kernel). >>>>>>>> >>>>>>>>Some people around those issues, seem to claim that the change >>>>>>>>mentioned in>>>>>>>>https://lists.proxmox.com/pipermail/pve-devel/2024- July/064614.html <https://lists.proxmox.com/pipermail/pve- devel/2024- July/064614.html>>>>>>>>>would fix the issue, which is as well backchannel related. >>>>>>>> >>>>>>>>This is upstream: 6ddc9deacc13 ("SUNRPC: Fix backchannel reply,>>>>>>>>again"). While this commit fixes 57331a59ac0d ("NFSv4.1: Use the >>>>>>>>nfs_client's rpc timeouts for backchannel") this is not something >>>>>>>>which goes back to 6.1.y, could it be possible that hte backchannel>>>>>>>>refactoring and this final fix indeeds fixes the issue? >>>>>>>>>>>>>>>>As people report it is not easily reproducible, so this makes it>>>>>>>>harder to identify fixes correctly. >>>>>>>> >>>>>>>>I gave a (short) stance on trying to backport commits up to>>>>>>>>6ddc9deacc13 ("SUNRPC: Fix backchannel reply, again") but this quickly>>>>>>>>seems to indicate it is probably still not the right thing for >>>>>>>>backporting to the older stable series. >>>>>>>> >>>>>>>>As at least pre-requisites: >>>>>>>> >>>>>>>>2009e32997ed568a305cf9bc7bf27d22e0f6ccda >>>>>>>>4119bd0306652776cb0b7caa3aea5b2a93aecb89 >>>>>>>>163cdfca341b76c958567ae0966bd3575c5c6192 >>>>>>>>f4afc8fead386c81fda2593ad6162271d26667f8 >>>>>>>>6ed8cdf967f7e9fc96cd1c129719ef99db2f9afc >>>>>>>>57331a59ac0d680f606403eb24edd3c35aecba31 >>>>>>>>>>>>>>>>and still there would be conflicting codepaths (and does not seem>>>>>>>>right). >>>>>>>>>>>>>>>>Chuck, Benjamin, Trond, is there anything we can provive on reporters>>>>>>>>side that we can try to tackle this issue better? >>>>>>>>>>>>>>As I've indicated before, NFSD should not block no matter what the >>>>>>>client may or may not be doing. I'd like to focus on the server first.>>>>>>> >>>>>>>What is the result of: >>>>>>> >>>>>>>$ cd <Bookworm's v6.1.90 kernel source > >>>>>>>$ unset KBUILD_OUTPUT >>>>>>>$ make -j `nproc` >>>>>>>$ scripts/faddr2line \ >>>>>>> fs/nfsd/nfs4state.o \ >>>>>>> nfsd4_destroy_session+0x16d >>>>>>> >>>>>>>Since this issue appeared after v6.1.1, is it possible to bisect >>>>>>>between v6.1.1 and v6.1.90 ? >>>>>> >>>>>>First please note, at least speaking of triggering the issue in>>>>>>Debian, Debian has moved to 6.1.119 based kernel already (and soon in>>>>>>the weekends point release move to 6.1.123). >>>>>>>>>>>>That said, one of the users which regularly seems to be hit by the >>>>>>issue was able to provide the above requested information, based for>>>>>>6.1.119: >>>>>> >>>>>>~/kernel/linux-source-6.1# make kernelversion >>>>>>6.1.119>>>>>>~/kernel/linux-source-6.1# scripts/faddr2line fs/nfsd/ nfs4state.o nfsd4_destroy_session+0x16d>>>>>>nfsd4_destroy_session+0x16d/0x250:>>>>>>__list_del_entry at /root/kernel/linux-source-6.1/./include/ linux/list.h:134 >>>>>>(inlined by) list_del at /root/kernel/linux-source-6.1/./ include/linux/list.h:148 >>>>>>(inlined by) unhash_session at /root/kernel/linux-source-6.1/ fs/ nfsd/nfs4state.c:2062 >>>>>>(inlined by) nfsd4_destroy_session at /root/kernel/linux- source-6.1/fs/nfsd/nfs4state.c:3856>>>>>>>>>>>>They could provide as well a decode_stacktrace output for the recent>>>>>>hit (if that is helpful for you): >>>>>>>>>>>>[Mon Jan 6 13:25:28 2025] INFO: task nfsd:55306 blocked for more than 6883 seconds. >>>>>>[Mon Jan 6 13:25:28 2025] Not tainted 6.1.0-28-amd64 #1 Debian 6.1.119-1 >>>>>>[Mon Jan 6 13:25:28 2025] "echo 0 > /proc/sys/kernel/ hung_task_timeout_secs" disables this message. >>>>>>[Mon Jan 6 13:25:28 2025] task:nfsd state:D stack:0 pid:55306 ppid:2 flags:0x00004000>>>>>>[Mon Jan 6 13:25:28 2025] Call Trace: >>>>>>[Mon Jan 6 13:25:28 2025] <TASK> >>>>>>[Mon Jan 6 13:25:28 2025] __schedule+0x34d/0x9e0 >>>>>>[Mon Jan 6 13:25:28 2025] schedule+0x5a/0xd0 >>>>>>[Mon Jan 6 13:25:28 2025] schedule_timeout+0x118/0x150 >>>>>>[Mon Jan 6 13:25:28 2025] wait_for_completion+0x86/0x160 >>>>>>[Mon Jan 6 13:25:28 2025] __flush_workqueue+0x152/0x420>>>>>>[Mon Jan 6 13:25:28 2025] nfsd4_destroy_session (debian/build/ build_amd64_none_amd64/include/linux/spinlock.h:351 debian/build/ build_amd64_none_amd64/fs/nfsd/nfs4state.c:3861) nfsd >>>>>>[Mon Jan 6 13:25:28 2025] nfsd4_proc_compound (debian/build/ build_amd64_none_amd64/fs/nfsd/nfs4proc.c:2680) nfsd >>>>>>[Mon Jan 6 13:25:28 2025] nfsd_dispatch (debian/build/ build_amd64_none_amd64/fs/nfsd/nfssvc.c:1022) nfsd >>>>>>[Mon Jan 6 13:25:28 2025] svc_process_common (debian/build/ build_amd64_none_amd64/net/sunrpc/svc.c:1344) sunrpc >>>>>>[Mon Jan 6 13:25:28 2025] ? svc_recv (debian/build/ build_amd64_none_amd64/net/sunrpc/svc_xprt.c:897) sunrpc >>>>>>[Mon Jan 6 13:25:28 2025] ? nfsd_svc (debian/build/ build_amd64_none_amd64/fs/nfsd/nfssvc.c:983) nfsd >>>>>>[Mon Jan 6 13:25:28 2025] ? nfsd_inet6addr_event (debian/ build/ build_amd64_none_amd64/fs/nfsd/nfssvc.c:922) nfsd >>>>>>[Mon Jan 6 13:25:28 2025] svc_process (debian/build/ build_amd64_none_amd64/net/sunrpc/svc.c:1474) sunrpc >>>>>>[Mon Jan 6 13:25:28 2025] nfsd (debian/build/ build_amd64_none_amd64/fs/nfsd/nfssvc.c:960) nfsd>>>>>>[Mon Jan 6 13:25:28 2025] kthread+0xd7/0x100 >>>>>>[Mon Jan 6 13:25:28 2025] ? kthread_complete_and_exit+0x20/0x20 >>>>>>[Mon Jan 6 13:25:28 2025] ret_from_fork+0x1f/0x30 >>>>>>[Mon Jan 6 13:25:28 2025] </TASK> >>>>>>>>>>>>The question about bisection is actually harder, those are production >>>>>>systems and I understand it's not possible to do bisect there, while>>>>>>unfortunately not reprodcing the issue on "lab conditions". >>>>>> >>>>>>Does the above give us still a clue on what you were looking for? >>>>> >>>>>Thanks for the update. >>>>>>>>>>It's possible that 38f080f3cd19 ("NFSD: Move callback_wq into struct >>>>>nfs4_client"), while not a specific fix for this issue, might offer some >>>>>relief by preventing the DESTROY_SESSION hang from affecting all other>>>>>clients of the degraded server. >>>>> >>>>>Not having a reproducer or the ability to bisect puts a damper on>>>>>things. The next step, then, is to enable tracing on servers where this >>>>>issue can come up, and wait for the hang to occur. The following command >>>>>captures information only about callback operation, so it should not>>>>>generate much data or impact server performance. >>>>> >>>>> # trace-cmd record -e nfsd:nfsd_cb\* >>>>>>>>>>Let that run until the problem occurs, then ^C, compress the resulting>>>>>trace.dat file, and either attach it to 1071562 or email it to me >>>>>privately. >>>>thanks for the follow-up. >>>>>>>>I am the "customer" with two affected file servers. We have since moved those >>>>servers to the backports kernel (6.11.10) in the hope of forward fixing the >>>>issue. If this kernel is stable, I'm afraid I can't go back to the 'bad' >>>>kernel (700+ researchers affected..), and we're also not able to trigger the>>>>issue on our test environment. >>> >>>Hello Dr. Herzog - >>> >>>If the problem recurs on 6.11, the trace-cmd I suggest above works >>>there as well. >>the bad news is: it just happened again with the bpo kernel. >>>>We then immediately started trace-cmd since usually there are several call>>traces in a row and we did get a trace.dat:>>http://people.phys.ethz.ch/~daduke/trace.dat <http:// people.phys.ethz.ch/~daduke/trace.dat>>>>>we did notice however that the stack trace looked a bit different this time:>> >> INFO: task nfsd:2566 blocked for more than 5799 seconds. >> Tainted: G W 6.11.10+bpo-amd64 #1 Debia> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables t> >> task:nfsd state:D stack:0 pid:2566 tgid:2566 > >> Call Trace: >> <TASK> >> __schedule+0x400/0xad0 >> schedule+0x27/0xf0 >> nfsd4_shutdown_callback+0xfe/0x140 [nfsd] >> ? __pfx_var_wake_function+0x10/0x10 >> __destroy_client+0x1f0/0x290 [nfsd] >> nfsd4_destroy_clientid+0xf1/0x1e0 [nfsd] >> ? svcauth_unix_set_client+0x586/0x5f0 [sunrpc] >> nfsd4_proc_compound+0x34d/0x670 [nfsd] >> nfsd_dispatch+0xfd/0x220 [nfsd] >> svc_process_common+0x2f7/0x700 [sunrpc] >> ? __pfx_nfsd_dispatch+0x10/0x10 [nfsd] >> svc_process+0x131/0x180 [sunrpc] >> svc_recv+0x830/0xa10 [sunrpc] >> ? __pfx_nfsd+0x10/0x10 [nfsd] >> nfsd+0x87/0xf0 [nfsd] >> kthread+0xcf/0x100 >> ? __pfx_kthread+0x10/0x10 >> ret_from_fork+0x31/0x50 >> ? __pfx_kthread+0x10/0x10 >> ret_from_fork_asm+0x1a/0x30 >> </TASK> >>>>and also the state of the offending client in `/proc/fs/nfsd/ clients/*/info` >>used to be callback state: UNKNOWN while now it is DOWN or FAULT. No idea>>what it means, but I thought it was worth mentioning. >> > >Looks like this is hung in nfsd41_cb_inflight_wait_complete() ? That >probably means that the cl_cb_inflight counter is stuck at >0. I'm >guessing that means that there is some callback that it's expecting to >complete that isn't. From nfsd4_shutdown_callback(): > > /* > * Note this won't actually result in a null callback; > * instead, nfsd4_run_cb_null() will detect the killed > * client, destroy the rpc client, and stop: > */ > nfsd4_run_cb(&clp->cl_cb_null); > flush_workqueue(clp->cl_callback_wq); > nfsd41_cb_inflight_wait_complete(clp); > >...it sounds like that isn't happening properly though. > >It might be interesting to see if you can track down the callback >client in /sys/kernel/debug/sunrpc and see what it's doing. Here's a possible scenario: The trace.dat shows the server is sending a lot of CB_RECALL_ANY operations. Normally a callback occurs only due to some particular client request. Such requests would be completed before a client unmounts. CB_RECALL_ANY is an operation which does not occur due to a particular client operation and can occur at any time. I believe this is the first operation of this type we've added to NFSD. My guess is that the server's laundromat has sent some CB_RECALL_ANY operations while the client is umounting -- DESTROY_SESSION is racing with those callback operations. deleg_reaper() was backported to 6.1.y in 6.1.81, which lines up more or less with when the issues started to show up. A quick way to test this theory would be to make deleg_reaper() a no-op. If this helps, then we know that shutting down the server's callback client needs to be more careful about cleaning up outstanding callbacks. -- Chuck LeverHello. Thanks a lot for all of this work ! I have started recording traces using : # trace-cmd record -e nfsd:nfsd_cb\*and currently waiting for the bug to trigger. This generally happen in one/two weeks for me.If you want I adjust some recording parameters let me know.After looking at your data and Rik's data, I decided to try reproducing the problem in my lab. No luck so far. The signatures of these issues are slightly different from each other: v6.1: - nfsd4_destroy_session hangs on the flush_workqueue in nfsd4_shutdown_callback() - There might be outstanding callback RPCs that are not exiting - Lots of CB_RECALL_ANY traffic. Only place that's generated in v6.1 is the NFSD shrinker when memory is short - There appear to be some unreachable clients -- evidence of client crashes or network outages, perhaps v6.12: - destroy_client() hangs on the wait_var_event in nfsd4_shtudown_callback() - There are no callback RPCs left after the hang - There are some stuck clients listed under /proc/fs/nfsd/ Similar, but not the same. I'm still open to clues, so please continue the regimen of starting the trace-cmd when the server boots, and doing an "echo t > /proc/sysrq-trigger" when the hang appears. # trace-cmd record -e nfsd:nfsd_cb\* -e sunrpc:svc_xprt_detach \ -p function -l nfsd4_destroy_sessionHello Chuck. Sorry for my late reply but I need to find something interesting for you. Did you see my call trace analyze here ? https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1071562 On v6.1 did you see that nfsd4_shutdown_callback is reached from both nfsd4 laundromat_main and nfsd4_state_shrinker_worker ? For me the hang in V6.1 come also from wait_var_event. Here the state of my RAM on my server with some load.total used free shared buff/cache available Mem: 32083 4982 651 5 26919 27101Swap: 16629 842 15787 My desktop clients use heavily suspend. The computer are almostnever rebooted. When a user logout, suspending is automatically launched. Do you think that some delegation can be accumulated,locked by many suspended host, and can cause the high memory/cache usage ?
v6.1 I think has courteous server support, meaning the server will attempt to preserve all client state when the client stops sending state-renewing operations. Suspended clients probably don't clean up their network connections. The server could see that as a network partition. Still, the server is supposed to clear out an idle connection after 6 minutes. So these hangs should clear up if this were the only issue.
Here my crash timeline between the desktop client salleprof13 (the one you think is unreachable) and the server fichdc02. The failure come from suspend. --- Client salleprof13 wake from sleep at 09:55:37 and was attached by the server. The callback channel is initialized. --- janv. 14 07:20:32 salleprofs13 kernel: PM: suspend entry (deep) janv. 14 09:55:37 salleprofs13 kernel: PM: suspend exitjanv. 14 09:55:37 salleprofs13 ModemManager[621]: <info> [sleep-monitor- systemd] system is resuming janv. 14 09:55:37 salleprofs13 NetworkManager[576]: <info> [1736844937.2382] manager: sleep: wake requested (sleeping: yes enabled: yes) janv. 14 09:55:37 salleprofs13 systemd[1]: Stopping gssd-bug.service - Gssd credential cache hook... janv. 14 09:55:37 salleprofs13 systemd[1]: Starting winbind.service - Samba Winbind Daemon... janv. 14 09:55:37 salleprofs13 systemd[1]: Started winbind.service - Samba Winbind Daemon. janv. 14 09:55:40 salleprofs13 NetworkManager[576]: <info> [1736844940.6304] device (enp2s0): carrier: link connected janv. 14 09:55:40 salleprofs13 kernel: r8169 0000:02:00.0 enp2s0: Link is Up - 1Gbps/Full - flow control offnfsd-1695 [047] ..... 190512.862590: nfsd_cb_probe: addr=172.16.118.121:0 client 67833e73:4dd32903 state=UNKNOWN kworker/u96:8-225529 [047] ..... 190512.862782: nfsd_cb_setup: addr=172.16.118.121:0 client 67833e73:4dd32903 proto=tcp flavor=sys kworker/u96:8-225529 [047] ..... 190512.862784: nfsd_cb_state: addr=172.16.118.121:0 client 67833e73:4dd32903 state=UP 2025-01-14T09:55:48.290546+01:00 fichdc02 rpc.mountd[1363]: v4.2 client attached: 0x4dd3290367833e73 from "172.16.118.121:825"--- Someone logon on the station. Immediately the server start sending nfsd_cb_recall_any. Strange no ? What can be recalled on that host that just wake up...
The server attempts to invoke CB_RECALL_ANY on all clients it knows about. If it believes the client has state (even when in courtesy) then the server will send this request to that client.
---janv. 14 09:55:53 salleprofs13 nfsrahead[121742]: setting /dnfs/wine readahead to 128 janv. 14 09:56:13 salleprofs13 systemd-logind[569]: New session 36 of user xxxxxxxx.kworker/u96:3-227781 [047] ..... 190541.974364: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:2-220501 [013] ..... 190541.977732: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0 kworker/u96:2-220501 [000] ..... 190550.387742: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:0-228547 [003] ..... 190550.389602: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0 kworker/u96:2-220501 [021] ..... 190565.367759: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:1-230409 [000] ..... 190565.371391: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0 kworker/u96:2-220501 [013] ..... 190579.748430: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:8-225529 [026] ..... 190579.749946: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0 kworker/u96:8-225529 [013] ..... 190592.749738: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:2-220501 [001] ..... 190592.751192: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0 kworker/u96:0-228547 [000] ..... 190599.849333: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:0-228547 [000] ..... 190599.850872: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0 kworker/u96:2-220501 [045] ..... 190686.760138: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:1-230409 [014] ..... 190686.761181: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0 kworker/u96:1-230409 [013] ..... 190694.103480: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:8-225529 [022] ..... 190694.106120: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0 kworker/u96:8-225529 [000] ..... 190749.678378: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:2-220501 [007] ..... 190749.679870: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0 kworker/u96:4-230705 [014] ..... 190782.830144: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:1-230409 [010] ..... 190782.831220: nfsd_cb_recall_any_done: client 67833e73:4dd32903 status=0--- Next the user suspend the host maybe by pressing the power button without login out so the last nfsd_cb_recall_any fail Maybe the "unrecognized reply" related ? ---janv. 14 10:01:18 salleprofs13 systemd-logind[569]: The system will suspend now! janv. 14 10:01:18 salleprofs13 NetworkManager[576]: <info> [1736845278.5631] manager: sleep: sleep requested (sleeping: no enabled: yes) janv. 14 10:01:18 salleprofs13 ModemManager[621]: <info> [sleep-monitor- systemd] system is about to suspendjanv. 14 10:01:20 salleprofs13 kernel: PM: suspend entry (deep)kworker/u96:2-220501 [047] ..... 190851.843698: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG kworker/u96:2-220501 [047] ..... 190861.062828: nfsd_cb_state: addr=172.16.118.121:0 client 67833e73:4dd32903 state=FAULT2025-01-14T10:06:06.586140+01:00 fichdc02 kernel: [191131.106081] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000ad57929d xid 52751431--- Got 5 unrecognized reply. Seems not related . ---2025-01-14T10:06:56.762137+01:00 fichdc02 kernel: [191181.279788] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000002dcd99c8 xid 5d819d7d 2025-01-14T10:06:56.762197+01:00 fichdc02 kernel: [191181.280005] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000002dcd99c8 xid 61819d7d 2025-01-14T10:06:56.762201+01:00 fichdc02 kernel: [191181.280054] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000002dcd99c8 xid 60819d7d 2025-01-14T10:06:56.762206+01:00 fichdc02 kernel: [191181.280223] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000002dcd99c8 xid 5f819d7d 2025-01-14T10:06:56.762209+01:00 fichdc02 kernel: [191181.280364] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000002dcd99c8 xid 5e819d7d---Just 10 minutes after suspend the host wake up (with xxxxxxxx still logged on).The gssd-bug.service is a custom script that kill all the user processes if the kerberos cache file has expired. This is due to a rpc.gssd bug that hammer the server when the cache has expired during suspend. It run "killall -u xxxxxxxx". But here, I don't know if the killall was called or not.Just after the wake. The server send again an nfsd_cb_recall_any. But this time there is no nfsd_cb_state with state=FAULT. From this time there no more kworkercb calls. I think this where the hang start.
I'm thinking the hang started a little earlier, but I agree that this is the first symptom of it. I was attempting to reproduce by periodically dropping the connection, but it appears there needs to be one or two more steps to make it behave like a suspended client. I will see what can be done.
And we got again an unrecognized reply. --- janv. 14 10:10:24 salleprofs13 kernel: PM: suspend exitjanv. 14 10:10:24 salleprofs13 systemd-sleep[124910]: System returned from sleep state. janv. 14 10:10:24 salleprofs13 systemd[1]: Stopping gssd-bug.service - Gssd credential cache hook... janv. 14 10:10:24 salleprofs13 NetworkManager[576]: <info> [1736845824.4117] manager: sleep: wake requested (sleeping: yes enabled: yes) janv. 14 10:10:24 salleprofs13 check-gssd-cache[124962]: id: « xxxxxxxx » : the user don't exist janv. 14 10:10:24 salleprofs13 systemd[1]: Started winbind.service - Samba Winbind Daemon. janv. 14 10:10:27 salleprofs13 kernel: r8169 0000:02:00.0 enp2s0: Link is Up - 1Gbps/Full - flow control off janv. 14 10:10:27 salleprofs13 NetworkManager[576]: <info> [1736845827.6412] device (enp2s0): carrier: link connected janv. 14 10:10:35 salleprofs13 systemd[1]: Stopped gssd-bug.service - Gssd credential cache hook.kworker/u96:2-220501 [012] ..... 191417.544355: nfsd_cb_recall_any: addr=172.16.118.121:825 client 67833e73:4dd32903 keep=0 bmval0=RDATA_DLG2025-01-14T10:10:58.426113+01:00 fichdc02 kernel: [191422.934976] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000007205cdb2 xid ee91a9d8--- nfsd probe a failed State. Normal. But as kworker hang, it can't reinit the callback channel after the nfsd_cb_state "state=UNKNOWN". I don't know why but nfsd started also to send nfsd_cb_recall... Note that is less than 120 second before the "BLOCKED" message. so the thread may be already locked. ---nfsd-1690 [014] ..... 191424.483249: nfsd_cb_probe: addr=172.16.118.121:0 client 67833e73:4dd32903 state=FAULT nfsd-1690 [014] ..... 191424.483252: nfsd_cb_state: addr=172.16.118.121:0 client 67833e73:4dd32903 state=UNKNOWN nfsd-1695 [013] ...1. 191441.265047: nfsd_cb_recall: addr=172.16.118.121:0 client 67833e73:4dd32903 stateid 00001c6e:00000001 nfsd-1695 [014] ...1. 191441.646104: nfsd_cb_recall: addr=172.16.118.121:0 client 67833e73:4dd32903 stateid 000015fc:00000001--- Got some strange logs on the client And 7 unrecognized reply on the server that seems not related. --- janv. 14 10:11:00 salleprofs13 PackageKit[122249]: daemon quitjanv. 14 10:11:00 salleprofs13 systemd[1]: packagekit.service: Deactivated successfully. janv. 14 10:11:00 salleprofs13 systemd[1]: packagekit.service: Consumed 28.223s CPU time. janv. 14 10:11:02 salleprofs13 gnome-shell[122127]: JS ERROR: Gio.IOErrorEnum: Erreur lors de l’appel de StartServiceByName pour org.vmware.viewagent.Credentials : Le délai d’>_injectToMethod/klass[method]@resource:///org/gnome/gjs/modules/core/ overrides/Gio.js:287:25VmwareCredentials@resource:///org/gnome/shell/gdm/vmware.js:34:10 VmwareCredentialsManager@resource:///org/gnome/shell/gdm/vmware.js:41:29 getVmwareCredentialsManager@resource:///org/gnome/shell/gdm/vmware.js:51:37 ShellUserVerifier@resource:///org/gnome/shell/gdm/util.js:183:64 _init@resource:///org/gnome/shell/gdm/authPrompt.js:74:30 AuthPrompt@resource:///org/gnome/shell/gdm/authPrompt.js:51:4 _ensureAuthPrompt@resource:///org/gnome/shell/ui/unlockDialog.js:686:32 _showPrompt@resource:///org/gnome/shell/ui/unlockDialog.js:725:14 vfunc_key_press_event@resource:///org/gnome/shell/ui/unlockDialog.js:620:14janv. 14 10:11:05 salleprofs13 gsd-power[122329]: Error setting property 'PowerSaveMode' on interface org.gnome.Mutter.DisplayConfig: Le délai d’attente est dépassé (g-io-erro> janv. 14 10:11:27 salleprofs13 gnome-shell[122127]: JS ERROR: Gio.IOErrorEnum: Erreur lors de l’appel de StartServiceByName pour org.vmware.viewagent.Credentials : Le délai d’>_injectToMethod/klass[method]@resource:///org/gnome/gjs/modules/core/ overrides/Gio.js:287:25VmwareCredentials@resource:///org/gnome/shell/gdm/vmware.js:34:10 VmwareCredentialsManager@resource:///org/gnome/shell/gdm/vmware.js:41:29 getVmwareCredentialsManager@resource:///org/gnome/shell/gdm/vmware.js:51:37 ShellUserVerifier@resource:///org/gnome/shell/gdm/util.js:183:64 _init@resource:///org/gnome/shell/gdm/authPrompt.js:74:30 AuthPrompt@resource:///org/gnome/shell/gdm/authPrompt.js:51:4 _ensureAuthPrompt@resource:///org/gnome/shell/ui/unlockDialog.js:686:32 _showPrompt@resource:///org/gnome/shell/ui/unlockDialog.js:725:14 vfunc_key_press_event@resource:///org/gnome/shell/ui/unlockDialog.js:620:142025-01-14T10:12:36.730114+01:00 fichdc02 kernel: [191521.235822] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000191d4459 xid d591b1ee 2025-01-14T10:12:36.730165+01:00 fichdc02 kernel: [191521.236547] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000191d4459 xid d691b1ee 2025-01-14T10:12:36.730169+01:00 fichdc02 kernel: [191521.236666] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000191d4459 xid da91b1ee 2025-01-14T10:12:36.730171+01:00 fichdc02 kernel: [191521.236743] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000191d4459 xid db91b1ee 2025-01-14T10:12:36.730172+01:00 fichdc02 kernel: [191521.236769] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000191d4459 xid d991b1ee 2025-01-14T10:12:36.730174+01:00 fichdc02 kernel: [191521.236824] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000191d4459 xid d891b1ee 2025-01-14T10:12:36.730177+01:00 fichdc02 kernel: [191521.236840] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000191d4459 xid d791b1ee--- And finally the hang syslog message ---2025-01-14T10:14:29.370164+01:00 fichdc02 kernel: [191633.871204] INFO: task nfsd:1690 blocked for more than 120 seconds. 2025-01-14T10:14:29.374846+01:00 fichdc02 kernel: [191633.875410] INFO: task nfsd:1691 blocked for more than 120 seconds. 2025-01-14T10:14:29.374966+01:00 fichdc02 kernel: [191633.878106] INFO: task nfsd:1693 blocked for more than 120 seconds. 2025-01-14T10:14:29.378303+01:00 fichdc02 kernel: [191633.880748] INFO: task nfsd:1695 blocked for more than 120 seconds.Hope this help. I'm still recording. Regards, Baptiste.
-- Chuck Lever
