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

Groups > linux.debian.kernel > #82523 > unrolled thread

Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session

Back to article view | Back to linux.debian.kernel

Contents

  Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session Martin Svec <martin.svec@zoner.cz> - 2024-05-21 11:50 +0200
    Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session Harald Dunkel <harri@afaics.de> - 2024-06-15 20:40 +0200
      Re: Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session Harald Dunkel <harri@afaics.de> - 2024-06-15 20:50 +0200
      Re: Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session Harald Dunkel <harri@afaics.de> - 2024-06-16 12:10 +0200
    Bug#1071562: Which NFS Version are you using? Thomas Glanzmann <thomas@glanzmann.de> - 2024-06-20 15:30 +0200
      Re: Bug#1071562: Which NFS Version are you using? Harald Dunkel <harald.dunkel@aixigo.com> - 2024-06-21 08:40 +0200
      Bug#1071562: Which NFS Version are you using? Martin Svec <martin.svec@zoner.cz> - 2024-06-27 12:40 +0200
    Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session Michael Gernoth <debian@zerfleddert.de> - 2024-06-26 11:40 +0200
    Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session "Pellegrin Baptiste" <Baptiste.Pellegrin@ac-grenoble.fr> - 2024-12-02 10:40 +0100
      Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session Salvatore Bonaccorso <carnil@debian.org> - 2024-12-25 10:30 +0100
    Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session Guillaume Sauvenay <guillaume.sauvenay@univ-eiffel.fr> - 2025-01-08 14:10 +0100

#82523 — Bug#1071562: nfsd blocks indefinitely in nfsd4_destroy_session

Package: nfs-kernel-server
Version: 1:2.6.2-4

Package: linux-image-6.1.0-21-amd64
Version: 6.1.90-1

During our tests of Proxmox VE with Debian NFS server as a shared storage we've noticed
that nfsd sometimes becomes unresponsive and it's necessary to reboot the server.

Probably the same error is reported here:
https://bugs.launchpad.net/ubuntu/+source/nfs-utils/+bug/2062568

NFS server:
* DELL PowerEdge R730xd, 2x 10C XEON E5-2640, Samsung SM863 SSDs, 8 GB RAM
* fresh installation of Debian Bookworm
* Linux 6.1.0-21-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.90-1 (2024-05-03) x86_64 GNU/Linux
* connected using 10GE link
* nfsd.conf configured with nthreads=16 (also tested with 8 and 4), other options left on defaults
* XFS mount exported with options: rw,sync,no_root_squash,no_subtree_check,no_wdelay

NFS client:
* DELL PowerEdge FC630, 2x 14C Xeon E5-2680 v4, 256 GB RAM
* fresh installation of Proxmox VE 8.2
* Proxmox Linux 6.8.4-3-pve kernel
* connected using 10GE link
* nfs client mount options: rw,noatime,nodiratime,vers=4.2,rsize=1048576,wsize=1048576,
   namlen=255,hard,proto=tcp,nconnect=8,max_connect=16,timeo=600,retrans=2,sec=sys,
   clientaddr=10.xx.xx.xx,local_lock=none,addr=10.xx.xx.xx

Dmesg on nfsd server side (repeats forever):

[ 3142.693181] INFO: task nfsd:1035 blocked for more than 120 seconds.
[ 3142.693217]       Not tainted 6.1.0-21-amd64 #1 Debian 6.1.90-1
[ 3142.693239] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3142.693264] task:nfsd            state:D stack:0     pid:1035  ppid:2      flags:0x00004000
[ 3142.693273] Call Trace:
[ 3142.693275]  <TASK>
[ 3142.693279]  __schedule+0x34d/0x9e0
[ 3142.693288]  schedule+0x5a/0xd0
[ 3142.693294]  schedule_timeout+0x118/0x150
[ 3142.693301]  wait_for_completion+0x86/0x160
[ 3142.693307]  __flush_workqueue+0x152/0x420
[ 3142.693317]  nfsd4_destroy_session+0x1b6/0x250 [nfsd]
[ 3142.693379]  nfsd4_proc_compound+0x355/0x660 [nfsd]
[ 3142.693433]  nfsd_dispatch+0x1a1/0x2b0 [nfsd]
[ 3142.693478]  svc_process_common+0x289/0x5e0 [sunrpc]
[ 3142.693551]  ? svc_recv+0x4e5/0x890 [sunrpc]
[ 3142.693631]  ? nfsd_svc+0x360/0x360 [nfsd]
[ 3142.693676]  ? nfsd_shutdown_threads+0x90/0x90 [nfsd]
[ 3142.693720]  svc_process+0xad/0x100 [sunrpc]
[ 3142.693790]  nfsd+0xd5/0x190 [nfsd]
[ 3142.693836]  kthread+0xda/0x100
[ 3142.693843]  ? kthread_complete_and_exit+0x20/0x20
[ 3142.693849]  ret_from_fork+0x22/0x30
[ 3142.693858]  </TASK>

Dump of nfsd threads:

/proc/1032/stack:
[<0>] svc_recv+0x7f3/0x890 [sunrpc]
[<0>] nfsd+0xc3/0x190 [nfsd]
[<0>] kthread+0xda/0x100
[<0>] ret_from_fork+0x22/0x30

/proc/1033/stack:
[<0>] svc_recv+0x7f3/0x890 [sunrpc]
[<0>] nfsd+0xc3/0x190 [nfsd]
[<0>] kthread+0xda/0x100
[<0>] ret_from_fork+0x22/0x30

/proc/1034/stack:
[<0>] svc_recv+0x7f3/0x890 [sunrpc]
[<0>] nfsd+0xc3/0x190 [nfsd]
[<0>] kthread+0xda/0x100
[<0>] ret_from_fork+0x22/0x30

/proc/1035/stack:
[<0>] __flush_workqueue+0x152/0x420
[<0>] nfsd4_destroy_session+0x1b6/0x250 [nfsd]
[<0>] nfsd4_proc_compound+0x355/0x660 [nfsd]
[<0>] nfsd_dispatch+0x1a1/0x2b0 [nfsd]
[<0>] svc_process_common+0x289/0x5e0 [sunrpc]
[<0>] svc_process+0xad/0x100 [sunrpc]
[<0>] nfsd+0xd5/0x190 [nfsd]
[<0>] kthread+0xda/0x100
[<0>] ret_from_fork+0x22/0x30

/proc/130/stack:
[<0>] rpc_shutdown_client+0xf2/0x150 [sunrpc]
[<0>] nfsd4_process_cb_update+0x4c/0x270 [nfsd]
[<0>] nfsd4_run_cb_work+0x9f/0x150 [nfsd]
[<0>] process_one_work+0x1c7/0x380
[<0>] worker_thread+0x4d/0x380
[<0>] kthread+0xda/0x100
[<0>] ret_from_fork+0x22/0x30

On NFS client side, there's a number of backchannel reply errors:

[78636.676789] RPC: Could not send backchannel reply error: -110
[78647.905675] RPC: Could not send backchannel reply error: -110
[78675.207201] RPC: Could not send backchannel reply error: -110
[78744.201603] RPC: Could not send backchannel reply error: -110
[78784.138769] RPC: Could not send backchannel reply error: -110

We're able to reproduce this bug quite often (several times a day) when
restoring a 500GB virtual machine image from Proxmox Backup Server to
NFS shared storage. On the other hand, we cannot trigger it by other
ways like random and/or sequential I/O fio stress tests. According to
iostat, the VM restore job writes to NFS server in 300-400 MiB batches
separated by 3-4 secs of inactivity.

Interestingly, this issue probably occurs only when using a recent kernel
on NFS client side. We're able to hit this bug only with Proxmox Linux
6.8.4-3-pve kernel on NFS client side. When using Proxmox 6.5.13-5-pve
kernel there're no client-side backchannel reply errors and nfsd server
runs without any hungs. It seems to me that changes in NFS client code
between 6.5.x and 6.8.x accidentally uncovered a race in nfsd server code.

Based on the bug report #2062568 in Ubuntu I assume this is not
a Proxmox-specific issue but Proxmox VM restore workload together
with our testing hardware setup makes it easier to hit.

Regards,
Martin

[toc] | [next] | [standalone]

#82727

metoo. I am not sure if a modern kernel on the clients is involved
(most clients are running 6.1.90), but I have seen a blocking nfsd
twice as well, last time this morning.

The kern.log on the server says

2024-06-10T15:54:23.722921+02:00 nasl006b kernel: [1298984.543582] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000038737b25 xid 0781d24a
2024-06-10T15:54:23.726900+02:00 nasl006b kernel: [1298984.546612] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000a26e4b2f xid be1192b1
2024-06-13T05:03:33.398937+02:00 nasl006b kernel: [1519133.667346] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000009ac82051 xid 45702eb1
2024-06-13T05:03:33.398953+02:00 nasl006b kernel: [1519133.667349] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000b0af5adf xid 63ccb60e
2024-06-13T05:03:33.398958+02:00 nasl006b kernel: [1519133.667353] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000004d687ff9 xid 0438a972
2024-06-13T05:03:33.398959+02:00 nasl006b kernel: [1519133.667359] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000009ae347c0 xid 7c0ce7c5
2024-06-13T05:03:33.398959+02:00 nasl006b kernel: [1519133.667368] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000c7b6b344 xid d288e075
2024-06-13T05:03:33.858956+02:00 nasl006b kernel: [1519134.125230] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000009ab8ef2e xid ccbb2f97
2024-06-13T05:03:34.070965+02:00 nasl006b kernel: [1519134.337681] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000024912b8e xid 370e512d
2024-06-15T05:04:25.622954+02:00 nasl006b kernel: [1691985.457249] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000033ef7c5b xid 6c326582
2024-06-15T05:04:25.622972+02:00 nasl006b kernel: [1691985.457258] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000027b8cd15 xid 2fc70243
2024-06-15T05:04:25.622973+02:00 nasl006b kernel: [1691985.457270] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000056a81005 xid b7a5e946
2024-06-15T05:04:25.622975+02:00 nasl006b kernel: [1691985.457281] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000004b75ece9 xid 96a47ca2
2024-06-15T05:04:25.622976+02:00 nasl006b kernel: [1691985.457292] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000076949917 xid cdb69ad9
2024-06-15T05:04:25.630912+02:00 nasl006b kernel: [1691985.465977] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000009ac82051 xid 59a52eb1
2024-06-15T05:04:25.638909+02:00 nasl006b kernel: [1691985.474956] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000076fb2b63 xid f8c4f93e
2024-06-15T05:04:25.666906+02:00 nasl006b kernel: [1691985.501189] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000a89fcf79 xid 40429a95
2024-06-15T05:04:25.710902+02:00 nasl006b kernel: [1691985.547423] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000024912b8e xid 4b43512d
2024-06-15T05:06:48.519438+02:00 nasl006b kernel: [1692128.349682]  <TASK>
2024-06-15T05:06:48.519451+02:00 nasl006b kernel: [1692128.349688]  schedule_timeout+0x118/0x150
2024-06-15T05:06:48.519452+02:00 nasl006b kernel: [1692128.349696]  nfsd4_destroy_session+0x1b6/0x250 [nfsd]
2024-06-15T05:06:48.519453+02:00 nasl006b kernel: [1692128.349748]  svc_process_common+0x289/0x5e0 [sunrpc]
2024-06-15T05:06:48.519454+02:00 nasl006b kernel: [1692128.349856]  nfsd+0xd5/0x190 [nfsd]
2024-06-15T05:06:48.519455+02:00 nasl006b kernel: [1692128.349882] INFO: task nfsd:3755 blocked for more than 120 seconds.
2024-06-15T05:06:48.566464+02:00 nasl006b kernel: [1692128.396723]  __flush_workqueue+0x152/0x420
2024-06-15T05:06:48.566474+02:00 nasl006b kernel: [1692128.396767]  nfsd_dispatch+0x1a1/0x2b0 [nfsd]
2024-06-15T05:06:48.566476+02:00 nasl006b kernel: [1692128.396813]  ? svc_recv+0x4e5/0x890 [sunrpc]
2024-06-15T05:06:48.566476+02:00 nasl006b kernel: [1692128.396861]  ? nfsd_shutdown_threads+0x90/0x90 [nfsd]
2024-06-15T05:06:48.566477+02:00 nasl006b kernel: [1692128.396906]  nfsd+0xd5/0x190 [nfsd]
2024-06-15T05:06:48.566478+02:00 nasl006b kernel: [1692128.396927]  ? kthread_complete_and_exit+0x20/0x20
2024-06-15T05:06:48.582911+02:00 nasl006b kernel: [1692128.420221] Call Trace:
2024-06-15T05:06:48.582924+02:00 nasl006b kernel: [1692128.420223]  __schedule+0x34d/0x9e0
2024-06-15T05:06:48.582925+02:00 nasl006b kernel: [1692128.420227]  schedule_timeout+0x118/0x150
2024-06-15T05:06:48.582926+02:00 nasl006b kernel: [1692128.420236]  nfsd4_create_session+0x792/0xba0 [nfsd]
2024-06-15T05:06:48.582927+02:00 nasl006b kernel: [1692128.420350]  ? nfsd_svc+0x360/0x360 [nfsd]
2024-06-15T05:08:49.257739+02:00 nasl006b kernel: [1692249.087884]  ? kthread_complete_and_exit+0x20/0x20
2024-06-15T05:08:49.257752+02:00 nasl006b kernel: [1692249.087891] INFO: task nfsd:3751 blocked for more than 241 seconds.
2024-06-15T05:08:49.274964+02:00 nasl006b kernel: [1692249.111185]  schedule+0x5a/0xd0
2024-06-15T05:08:49.274970+02:00 nasl006b kernel: [1692249.111217]  nfsd4_proc_compound+0x355/0x660 [nfsd]
2024-06-15T05:08:49.274972+02:00 nasl006b kernel: [1692249.111396]  </TASK>
2024-06-15T10:35:35.362972+02:00 nasl006b kernel: [1711855.148748] br0: port 2(vethbOt89W) entered disabled state
2024-06-15T10:37:19.606937+02:00 nasl006b kernel: [1711959.393773] br0: port 7(vethEcftre) entered disabled state
2024-06-15T10:37:20.426956+02:00 nasl006b kernel: [1711960.210911] br0: port 7(vethEcftre) entered disabled state
2024-06-15T10:37:20.426966+02:00 nasl006b kernel: [1711960.210989] device vethEcftre left promiscuous mode
2024-06-15T10:37:20.426967+02:00 nasl006b kernel: [1711960.210996] br0: port 7(vethEcftre) entered disabled state
2024-06-15T10:37:31.750960+02:00 nasl006b kernel: [1711971.535013] br0: port 8(vethtaVw4v) entered disabled state
2024-06-15T10:37:31.750972+02:00 nasl006b kernel: [1711971.535143] device vethtaVw4v left promiscuous mode
2024-06-15T10:37:31.750974+02:00 nasl006b kernel: [1711971.535150] br0: port 8(vethtaVw4v) entered disabled state

There was no such problem for Bullseye.


Regards

Harri

[toc] | [prev] | [next] | [standalone]

#82728

PS: I am not using Proxmox in this case, but native Debian 12. nfsd
is running inside an LXC container.

Regards
Harri

[toc] | [prev] | [next] | [standalone]

#82729

PS: I am not using Proxmox (here), but the nfsd was running inside
a LXC container. The container couldn't be stopped due to the stuck
service and the whole LXC server had to be restarted.

[toc] | [prev] | [next] | [standalone]

#82774 — Bug#1071562: Which NFS Version are you using?

Hello,
since I have also three productions systems with proxmox and bookworm nfs
servers which did not show the issue, I wonder which NFS version you're
using? I use nfs version 3.

Cheers,
        Thomas

[toc] | [prev] | [next] | [standalone]

#82780 — Re: Bug#1071562: Which NFS Version are you using?

On 2024-06-20 15:16:50, Thomas Glanzmann wrote:
> Hello,
> since I have also three productions systems with proxmox and bookworm nfs
> servers which did not show the issue, I wonder which NFS version you're
> using? I use nfs version 3.
> 
> Cheers,
>          Thomas
> 

I am using NFS version 4, e.g.

% grep -i nfs </proc/self/mounts
nfs-data:/space/data /data nfs4 rw,noatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=192.168.97.128,local_lock=none,addr=192.168.96.205 0 0
nfs-data:/space/home /home nfs4 rw,noatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=192.168.97.128,local_lock=none,addr=192.168.96.205 0 0

Regards
Harri

[toc] | [prev] | [next] | [standalone]

#82854 — Bug#1071562: Which NFS Version are you using?

Hello Thomas,

we use NFS v4.2 everywhere, see the specs in my bug report above. I didn't test it with different 
NFS versions.

Martin

[toc] | [prev] | [next] | [standalone]

#82842

Hello,

happened to me too, now a third time. The first two times on 6.1.85 and
now on 6.1.90 on the server. Clients are primarily Proxmox hosts running
Linux 6.5.13. NFS Version is 4.2.

This didn't happen with a very old kernel 6.1.0-9 from May 2023 which we
were running previously.

================================================================================
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000000b90a020 xid 7aa02cc0
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000012521bac xid db1882c6
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000001983dd82 xid c8e8428b
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000001ed9ceeb xid 9e09a079
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000b65a955d xid 8eee3a15
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000005706134e xid 1de36c93
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000f9d48ca3 xid 366cd575
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000a25621a3 xid 04908592
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000b27bf2f5 xid 2bf8d75e
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000002041e651 xid 331c9f24
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000bb856d0c xid 35c41e07
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000cf8f7523 xid e7ebe821
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000061496440 xid d1e84119
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000bd100f39 xid c2770460
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000001639729a xid 2eb64435
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000031316e4d xid 63f934ac
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000002f831e3b xid e1e5bdff
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000002d3c5c60 xid 89e3910b
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 0000000021afae1a xid e45a86a1
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000003e5a70d5 xid 933234ed
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000d0dffd1d xid 602eb73f
[Wed Jun 26 10:59:34 2024] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000006496e8c0 xid 7d3a4d97
[Wed Jun 26 11:03:56 2024] INFO: task nfsd:2007 blocked for more than 120 seconds.
[Wed Jun 26 11:03:56 2024]       Not tainted 6.1.0-21-amd64 #1 Debian 6.1.90-1
[Wed Jun 26 11:03:56 2024] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Wed Jun 26 11:03:56 2024] task:nfsd            state:D stack:0     pid:2007  ppid:2      flags:0x00004000
[Wed Jun 26 11:03:56 2024] Call Trace:
[Wed Jun 26 11:03:56 2024]  <TASK>
[Wed Jun 26 11:03:56 2024]  __schedule+0x34d/0x9e0
[Wed Jun 26 11:03:56 2024]  schedule+0x5a/0xd0
[Wed Jun 26 11:03:56 2024]  schedule_timeout+0x118/0x150
[Wed Jun 26 11:03:56 2024]  wait_for_completion+0x86/0x160
[Wed Jun 26 11:03:56 2024]  __flush_workqueue+0x152/0x420
[Wed Jun 26 11:03:56 2024]  nfsd4_destroy_session+0x1b6/0x250 [nfsd]
[Wed Jun 26 11:03:56 2024]  nfsd4_proc_compound+0x355/0x660 [nfsd]
[Wed Jun 26 11:03:56 2024]  nfsd_dispatch+0x1a1/0x2b0 [nfsd]
[Wed Jun 26 11:03:56 2024]  svc_process_common+0x289/0x5e0 [sunrpc]
[Wed Jun 26 11:03:56 2024]  ? svc_recv+0x4e5/0x890 [sunrpc]
[Wed Jun 26 11:03:56 2024]  ? nfsd_svc+0x360/0x360 [nfsd]
[Wed Jun 26 11:03:56 2024]  ? nfsd_shutdown_threads+0x90/0x90 [nfsd]
[Wed Jun 26 11:03:56 2024]  svc_process+0xad/0x100 [sunrpc]
[Wed Jun 26 11:03:56 2024]  nfsd+0xd5/0x190 [nfsd]
[Wed Jun 26 11:03:56 2024]  kthread+0xda/0x100
[Wed Jun 26 11:03:56 2024]  ? kthread_complete_and_exit+0x20/0x20
[Wed Jun 26 11:03:56 2024]  ret_from_fork+0x22/0x30
[Wed Jun 26 11:03:56 2024]  </TASK>
...
================================================================================

There were no "Got unrecognized reply" messages prior to that in the log.

Regards,
  Michael

[toc] | [prev] | [next] | [standalone]

#84718

[Multipart message — attachments visible in raw view] — view raw

Hello.

I try to address this bug without success for 4 months since I upgraded my two file servers to Debian Bookworm on August 2024. Finding a solution is critical for me as I manage a high school network where home directories are shared by NFS and actually I have a crash every week. But my situation may help to find what's wrong because the crash occur relatively often.

Here my current investigation.

The three last stable Debian Linux kernels seems all affected by this bug on the server side : 6.1.112-1, 6.1.115-1, 6.1.119+1. I have not tested any previous Bookworm version actually. Is difficult for me to give the exact client kernel version as I have around 450 Debian Bookworm Desktop all configured with automatic upgrades. But they may be not rebooted/powered on for a long time. And I don't know actually how to determine witch client causing the crash.


My two servers have completely different hardware and one is bare metal and the other is virtualized. So it seems not an hardware related problem.

The crash always occur when there is some load on the servers. But there is no need to very high load. Sometimes the problem occur with very few students working (around 75 clients).

Very strangely, in my case, the problem occur exactly one time per week, on one server. So I first thought about a log rotation problem. But I didn't find any clues in this direction.

Load balancing don't resolve the issue. At first the problem always occur on my "server1". After gradually migrating users to server2 it now occur on "server2". 

Very strangely the problem never occur two times in a short period of time. This may me think about some memory leaking or cache/swaping problem. I will try to reboot the servers every days to see if this change something.

I have approximately 40 "receive_cb_reply: Got unrecognized reply: calldir" messages per weeks on each servers. But these messages not always produce the crash. But there is always one or two "receive_cb_reply: Got unrecognized reply: calldir" messages before the crash. Like this :

(crash 1)
2024-11-07T17:43:33.879937+01:00 fichdc01 kernel: [372607.103736] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000639ae95e xid c9c4c5ef
2024-11-07T17:43:33.879942+01:00 fichdc01 kernel: [372607.103760] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000639ae95e xid c8c4c5ef
2024-11-07T17:46:07.480005+01:00 fichdc01 kernel: [372760.700382] INFO: task nfsd:1376 blocked for more than 120 seconds. 

(crash 2)
2024-11-15T10:12:25.053735+01:00 fichdc01 kernel: [450557.120399] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000005ab3e3a5 xid bf5c5798
2024-11-15T10:12:25.053755+01:00 fichdc01 kernel: [450557.120616] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000005ab3e3a5 xid c05c5798
2024-11-15T10:14:43.805798+01:00 fichdc01 kernel: [450695.869270] INFO: task nfsd:1357 blocked for more than 120 seconds.

(crash 3)
2024-11-22T09:17:47.855807+01:00 fichdc01 kernel: [224734.495096] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000008cac1606 xid b17462f6
2024-11-22T09:19:58.535823+01:00 fichdc01 kernel: [224865.170751] INFO: task nfsd:1438 blocked for more than 120 seconds.

(crash 4)
2024-11-29T16:06:00.541594+01:00 fichdc02 kernel: [240859.889516] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000004d6a097d xid f86a9543
2024-11-29T16:06:00.541622+01:00 fichdc02 kernel: [240859.890673] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000004d6a097d xid f96a9543
2024-11-29T16:09:13.053724+01:00 fichdc02 kernel: [241052.394494] INFO: task nfsd:1733 blocked for more than 120 seconds.


Follow 8~10 "nfsd blocked" messages. Every 120 seconds :

2024-11-29T16:09:13.053724+01:00 fichdc02 kernel: [241052.394494] INFO: task nfsd:1733 blocked for more than 120 seconds.
2024-11-29T16:09:13.054029+01:00 fichdc02 kernel: [241052.398245] INFO: task nfsd:1734 blocked for more than 120 seconds.
2024-11-29T16:09:13.057722+01:00 fichdc02 kernel: [241052.400733] INFO: task nfsd:1735 blocked for more than 120 seconds.
2024-11-29T16:11:13.885945+01:00 fichdc02 kernel: [241173.222137] INFO: task nfsd:1732 blocked for more than 120 seconds.
2024-11-29T16:11:13.886106+01:00 fichdc02 kernel: [241173.224428] INFO: task nfsd:1733 blocked for more than 241 seconds.
2024-11-29T16:11:13.890152+01:00 fichdc02 kernel: [241173.226583] INFO: task nfsd:1734 blocked for more than 241 seconds.
2024-11-29T16:11:13.890241+01:00 fichdc02 kernel: [241173.228945] INFO: task nfsd:1735 blocked for more than 241 seconds. 

Strangely sometimes, some clients that have already opened an NFS session can still access the server during about 30 minutes. But no new connections are allowed. After 30 minutes everything is blocked. And I can't restart the server normally or kill nfsd. I use sysrq to reboot immediately the servers...

Sometimes the server access is stopped immediately after the "nfsd blocked" error messages.

The first "nfsd blocked message" is always related to "nfsd4_destroy_session". The follow are related to "nfsd4_destroy_session", "nfsd4_create_session", or "nfsd4_shutdown_callback".

Since 6.1.115 have have also some kworker error messages like this :

INFO: task kworker/u96:2:39983 blocked for more than 120 seconds.
Not tainted 6.1.0-28-amd64 #1 Debian 6.1.119-1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u96:2 state:D stack:0 pid:39983 ppid:2 flags:0x00004000
Workqueue: nfsd4 laundromat_main [nfsd]
Call Trace:
<TASK>
__schedule+0x34d/0x9e0
schedule+0x5a/0xd0
schedule_timeout+0x118/0x150
wait_for_completion+0x86/0x160
__flush_workqueue+0x152/0x420
nfsd4_shutdown_callback+0x49/0x130 [nfsd]
? _raw_spin_unlock+0xa/0x30
? nfsd4_return_all_client_layouts+0xc4/0xf0 [nfsd]
? nfsd4_shutdown_copy+0x28/0x130 [nfsd]
__destroy_client+0x1f3/0x290 [nfsd]
nfs4_process_client_reaplist+0xa2/0x110 [nfsd]
laundromat_main+0x1ce/0x880 [nfsd]
process_one_work+0x1c7/0x380
worker_thread+0x4d/0x380
? rescuer_thread+0x3a0/0x3a0
kthread+0xda/0x100
? kthread_complete_and_exit+0x20/0x20
ret_from_fork+0x22/0x30
</TASK>

task:kworker/u96:3 state:D stack:0 pid:40084 ppid:2 flags:0x00004000
Workqueue: nfsd4 nfsd4_state_shrinker_worker [nfsd]
Call Trace:
<TASK>
__schedule+0x34d/0x9e0
schedule+0x5a/0xd0
schedule_timeout+0x118/0x150
wait_for_completion+0x86/0x160
__flush_workqueue+0x152/0x420
nfsd4_shutdown_callback+0x49/0x130 [nfsd]
? _raw_spin_unlock+0xa/0x30
? nfsd4_return_all_client_layouts+0xc4/0xf0 [nfsd]
? nfsd4_shutdown_copy+0x28/0x130 [nfsd]
__destroy_client+0x1f3/0x290 [nfsd]
nfs4_process_client_reaplist+0xa2/0x110 [nfsd]
nfsd4_state_shrinker_worker+0xf7/0x320 [nfsd]
process_one_work+0x1c7/0x380
worker_thread+0x4d/0x380
? rescuer_thread+0x3a0/0x3a0
kthread+0xda/0x100
? kthread_complete_and_exit+0x20/0x20
ret_from_fork+0x22/0x30
</TASK>

I can do more investigation if someone give me something to do. Actually I have no more ideas. And I don't now how determine the client causing the "unrecognized reply" messages.

Here some other links talking about this bug :

https://lore.kernel.org/all/987ec8b2-40da-4745-95c2-8ffef061c66f@aixigo.com/T/
https://forum.openmediavault.org/index.php?thread/52851-nfs-crash/
https://forum.proxmox.com/threads/kernel-6-8-x-nfs-server-bug.154272/
https://forums.truenas.com/t/truenas-nfs-random-crash/9200/34

Regards,

Baptiste.

[toc] | [prev] | [next] | [standalone]

#84935

Hi all,

On Mon, Dec 02, 2024 at 10:25:09AM +0100, Pellegrin Baptiste wrote:
> Hello.
> 
> I try to address this bug without success for 4 months since I upgraded my two file servers to Debian Bookworm on August 2024. Finding a solution is critical for me as I manage a high school network where home directories are shared by NFS and actually I have a crash every week. But my situation may help to find what's wrong because the crash occur relatively often.
> 
> Here my current investigation.
> 
> The three last stable Debian Linux kernels seems all affected by this bug on the server side : 6.1.112-1, 6.1.115-1, 6.1.119+1. I have not tested any previous Bookworm version actually. Is difficult for me to give the exact client kernel version as I have around 450 Debian Bookworm Desktop all configured with automatic upgrades. But they may be not rebooted/powered on for a long time. And I don't know actually how to determine witch client causing the crash.
> 
> 
> My two servers have completely different hardware and one is bare metal and the other is virtualized. So it seems not an hardware related problem.
> 
> The crash always occur when there is some load on the servers. But there is no need to very high load. Sometimes the problem occur with very few students working (around 75 clients).
> 
> Very strangely, in my case, the problem occur exactly one time per week, on one server. So I first thought about a log rotation problem. But I didn't find any clues in this direction.
> 
> Load balancing don't resolve the issue. At first the problem always occur on my "server1". After gradually migrating users to server2 it now occur on "server2". 
> 
> Very strangely the problem never occur two times in a short period of time. This may me think about some memory leaking or cache/swaping problem. I will try to reboot the servers every days to see if this change something.
> 
> I have approximately 40 "receive_cb_reply: Got unrecognized reply: calldir" messages per weeks on each servers. But these messages not always produce the crash. But there is always one or two "receive_cb_reply: Got unrecognized reply: calldir" messages before the crash. Like this :
> 
> (crash 1)
> 2024-11-07T17:43:33.879937+01:00 fichdc01 kernel: [372607.103736] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000639ae95e xid c9c4c5ef
> 2024-11-07T17:43:33.879942+01:00 fichdc01 kernel: [372607.103760] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 00000000639ae95e xid c8c4c5ef
> 2024-11-07T17:46:07.480005+01:00 fichdc01 kernel: [372760.700382] INFO: task nfsd:1376 blocked for more than 120 seconds. 
> 
> (crash 2)
> 2024-11-15T10:12:25.053735+01:00 fichdc01 kernel: [450557.120399] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000005ab3e3a5 xid bf5c5798
> 2024-11-15T10:12:25.053755+01:00 fichdc01 kernel: [450557.120616] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000005ab3e3a5 xid c05c5798
> 2024-11-15T10:14:43.805798+01:00 fichdc01 kernel: [450695.869270] INFO: task nfsd:1357 blocked for more than 120 seconds.
> 
> (crash 3)
> 2024-11-22T09:17:47.855807+01:00 fichdc01 kernel: [224734.495096] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000008cac1606 xid b17462f6
> 2024-11-22T09:19:58.535823+01:00 fichdc01 kernel: [224865.170751] INFO: task nfsd:1438 blocked for more than 120 seconds.
> 
> (crash 4)
> 2024-11-29T16:06:00.541594+01:00 fichdc02 kernel: [240859.889516] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000004d6a097d xid f86a9543
> 2024-11-29T16:06:00.541622+01:00 fichdc02 kernel: [240859.890673] receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt 000000004d6a097d xid f96a9543
> 2024-11-29T16:09:13.053724+01:00 fichdc02 kernel: [241052.394494] INFO: task nfsd:1733 blocked for more than 120 seconds.
> 
> 
> Follow 8~10 "nfsd blocked" messages. Every 120 seconds :
> 
> 2024-11-29T16:09:13.053724+01:00 fichdc02 kernel: [241052.394494] INFO: task nfsd:1733 blocked for more than 120 seconds.
> 2024-11-29T16:09:13.054029+01:00 fichdc02 kernel: [241052.398245] INFO: task nfsd:1734 blocked for more than 120 seconds.
> 2024-11-29T16:09:13.057722+01:00 fichdc02 kernel: [241052.400733] INFO: task nfsd:1735 blocked for more than 120 seconds.
> 2024-11-29T16:11:13.885945+01:00 fichdc02 kernel: [241173.222137] INFO: task nfsd:1732 blocked for more than 120 seconds.
> 2024-11-29T16:11:13.886106+01:00 fichdc02 kernel: [241173.224428] INFO: task nfsd:1733 blocked for more than 241 seconds.
> 2024-11-29T16:11:13.890152+01:00 fichdc02 kernel: [241173.226583] INFO: task nfsd:1734 blocked for more than 241 seconds.
> 2024-11-29T16:11:13.890241+01:00 fichdc02 kernel: [241173.228945] INFO: task nfsd:1735 blocked for more than 241 seconds. 
> 
> Strangely sometimes, some clients that have already opened an NFS session can still access the server during about 30 minutes. But no new connections are allowed. After 30 minutes everything is blocked. And I can't restart the server normally or kill nfsd. I use sysrq to reboot immediately the servers...
> 
> Sometimes the server access is stopped immediately after the "nfsd blocked" error messages.
> 
> The first "nfsd blocked message" is always related to "nfsd4_destroy_session". The follow are related to "nfsd4_destroy_session", "nfsd4_create_session", or "nfsd4_shutdown_callback".
> 
> Since 6.1.115 have have also some kworker error messages like this :
> 
> INFO: task kworker/u96:2:39983 blocked for more than 120 seconds.
> Not tainted 6.1.0-28-amd64 #1 Debian 6.1.119-1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:kworker/u96:2 state:D stack:0 pid:39983 ppid:2 flags:0x00004000
> Workqueue: nfsd4 laundromat_main [nfsd]
> Call Trace:
> <TASK>
> __schedule+0x34d/0x9e0
> schedule+0x5a/0xd0
> schedule_timeout+0x118/0x150
> wait_for_completion+0x86/0x160
> __flush_workqueue+0x152/0x420
> nfsd4_shutdown_callback+0x49/0x130 [nfsd]
> ? _raw_spin_unlock+0xa/0x30
> ? nfsd4_return_all_client_layouts+0xc4/0xf0 [nfsd]
> ? nfsd4_shutdown_copy+0x28/0x130 [nfsd]
> __destroy_client+0x1f3/0x290 [nfsd]
> nfs4_process_client_reaplist+0xa2/0x110 [nfsd]
> laundromat_main+0x1ce/0x880 [nfsd]
> process_one_work+0x1c7/0x380
> worker_thread+0x4d/0x380
> ? rescuer_thread+0x3a0/0x3a0
> kthread+0xda/0x100
> ? kthread_complete_and_exit+0x20/0x20
> ret_from_fork+0x22/0x30
> </TASK>
> 
> task:kworker/u96:3 state:D stack:0 pid:40084 ppid:2 flags:0x00004000
> Workqueue: nfsd4 nfsd4_state_shrinker_worker [nfsd]
> Call Trace:
> <TASK>
> __schedule+0x34d/0x9e0
> schedule+0x5a/0xd0
> schedule_timeout+0x118/0x150
> wait_for_completion+0x86/0x160
> __flush_workqueue+0x152/0x420
> nfsd4_shutdown_callback+0x49/0x130 [nfsd]
> ? _raw_spin_unlock+0xa/0x30
> ? nfsd4_return_all_client_layouts+0xc4/0xf0 [nfsd]
> ? nfsd4_shutdown_copy+0x28/0x130 [nfsd]
> __destroy_client+0x1f3/0x290 [nfsd]
> nfs4_process_client_reaplist+0xa2/0x110 [nfsd]
> nfsd4_state_shrinker_worker+0xf7/0x320 [nfsd]
> process_one_work+0x1c7/0x380
> worker_thread+0x4d/0x380
> ? rescuer_thread+0x3a0/0x3a0
> kthread+0xda/0x100
> ? kthread_complete_and_exit+0x20/0x20
> ret_from_fork+0x22/0x30
> </TASK>
> 
> I can do more investigation if someone give me something to do. Actually I have no more ideas. And I don't now how determine the client causing the "unrecognized reply" messages.
> 
> Here some other links talking about this bug :
> 
> https://lore.kernel.org/all/987ec8b2-40da-4745-95c2-8ffef061c66f@aixigo.com/T/
> https://forum.openmediavault.org/index.php?thread/52851-nfs-crash/
> https://forum.proxmox.com/threads/kernel-6-8-x-nfs-server-bug.154272/
> https://forums.truenas.com/t/truenas-nfs-random-crash/9200/34

I followed up upstream in
https://lore.kernel.org/linux-nfs/Z2vNQ6HXfG_LqBQc@eldamar.lan/T/#u
and related there seem to be as well
https://lore.kernel.org/linux-nfs/853bd2973f751e681476d320f23d47332d2bf41a.camel@kernel.org/
.

Regards,
Salvatore

[toc] | [prev] | [next] | [standalone]

#85054

[Multipart message — attachments visible in raw view] — view raw

Hello.
We were having the same kind of problem on our NFS servers in bookworm.
Since we installed Bookworm's backported kernel 6.11.5+bpo-amd64 five 
weeks ago on our NFS servers, the problem seems to have disappeared.
No more calldir errors in the logs, nor NFS hangs.
Regards
Guillaume

-- 
Département d'Appui à la pédagogie DGDIN-DAP
Université Gustave Eiffel
batiment copernic, 4e étage, 4B214
5 Bd Descartes - Champs sur Marne 77420
Tel : 01 60 95 74 55

[toc] | [prev] | [standalone]

Back to top | Article view | linux.debian.kernel

csiph-web