Re: NFSD threads hang when destroying a session or client ID

Harald Dunkel
2025-02-21T13:57:50Z

[-- Attachment #1: Type: text/plain, Size: 2636 bytes --]

Hi folks,

I don't like to bring bad news, but yesterday I had a problem with kernel 6.12.9 (twice), see attachment. AFAIK 6.12.9 is supposed to include 961b4b5e86bf56a2e4b567f81682defa5cba957e and 8626664c87eebb21a40d4924b2f244a1f56d8806.

Regards
Harri

________________________________________
From: Salvatore Bonaccorso <salvatore.bonaccorso@gmail.com> on behalf of Salvatore Bonaccorso <carnil@debian.org>
Sent: Friday, February 21, 2025 14:42
To: Baptiste PELLEGRIN via Bugspray Bot
Cc: anna@kernel.org; jlayton@kernel.org; cel@kernel.org; herzog@phys.ethz.ch; tom@talpey.com; trondmy@kernel.org; benoit.gschwind@minesparis.psl.eu; baptiste.pellegrin@ac-grenoble.fr; linux-nfs@vger.kernel.org; Harald Dunkel; chuck.lever@oracle.com
Subject: Re: NFSD threads hang when destroying a session or client ID

Hi,

On Mon, Feb 10, 2025 at 12:05:32PM +0000, Baptiste PELLEGRIN via Bugspray Bot wrote:
> Baptiste PELLEGRIN writes via Kernel.org Bugzilla:
>
> Hello.
>
> Good news for 6.1 kernels.
>
> With these patches applied :
>
> 8626664c87ee NFSD: Replace dprintks in nfsd4_cb_sequence_done()
> 961b4b5e86bf NFSD: Reset cb_seq_status after NFS4ERR_DELAY
>
> No hangs anymore for me since more than two weeks of server uptime. And previously the hangs occurred every weeks.
>
> I just see some suspicious server load maybe caused by the send of RPC_RECALL_ANY to shutdown/suspended/courtesy clients.
>
> I see a lot of work on the list that try to address these problems :
>
> nfsd: eliminate special handling of NFS4ERR_SEQ_MISORDERED
> nfsd: handle NFS4ERR_BADSLOT on CB_SEQUENCE better
> nfsd: when CB_SEQUENCE gets ESERVERFAULT don't increment seq_nr
> nfsd: only check RPC_SIGNALLED() when restarting rpc_task
> nfsd: always release slot when requeueing callback
> nfsd: lift NFSv4.0 handling out of nfsd4_cb_sequence_done()
> nfsd: prepare nfsd4_cb_sequence_done() for error handling rework
>
> NFSD: Skip sending CB_RECALL_ANY when the backchannel isn't up
>
> NFSD: fix hang in nfsd4_shutdown_callback

So I see the backport of 961b4b5e86bf NFSD: Reset cb_seq_status after
NFS4ERR_DELAY landed in the just released 6.1.129 stable version.

Do we consider this to be sufficient to have stabilized the situation
about this issue? (I do realize much other work has dne as well which
partially has flown down to stable series already).

This reply is mainly in focus of https://bugs.debian.org/1071562

Regards,
Salvatore
District Court Aachen - HRB 8057
Management Board: Arnaud Picut (CEO), Hicham El Bonne (CTO)
Chairman of the Supervisory Board: Benjamin Carl Lucas

[-- Attachment #2: x2 --]
[-- Type: application/octet-stream, Size: 6348 bytes --]

2025-02-20T15:45:09.658208+01:00 srvl056 kernel: [ 851.525553] ------------[ cut here ]------------
2025-02-20T15:45:09.658229+01:00 srvl056 kernel: [ 851.530874] cb_status=-521 tk_status=-10036
2025-02-20T15:45:09.658232+01:00 srvl056 kernel: [ 851.530922] WARNING: CPU: 2 PID: 1364 at fs/nfsd/nfs4callback.c:1339 nfsd4_cb_done+0x4e5/0x550 [nfsd]
2025-02-20T15:45:09.769527+01:00 srvl056 kernel: [ 851.546343] Modules linked in: rpcsec_gss_krb5 target_core_user uio target_core_pscsi target_core_file target_core_iblock iscsi_target_mod target_core_mod nvme_fabrics nvme_keyring nvme_core nvme_auth binfmt_misc nls_ascii nls_cp437 vfat fat intel_rapl_msr intel_rapl_common intel_uncore_frequency intel_uncore_frequency_common x86_pkg_temp_thermal intel_powerclamp coretemp ppdev jc42 rapl intel_cstate iTCO_wdt intel_pmc_bxt intel_uncore mei_me pcspkr ee1004 iTCO_vendor_support parport_pc watchdog intel_wmi_thunderbolt intel_pch_thermal mei parport intel_pmc_core ie31200_edac intel_vsec intel_vbtn joydev evdev sg sparse_keymap pmt_telemetry pmt_class ipmi_ssif acpi_power_meter acpi_pad button acpi_ipmi ipmi_si ipmi_devintf ipmi_msghandler loop drm efi_pstore nfsd configfs nfs_acl lockd grace auth_rpcgss sunrpc ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 btrfs blake2b_generic efivarfs raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c crc32c_generic raid1 raid0 md_mod
2025-02-20T15:45:09.803549+01:00 srvl056 kernel: [ 851.546530] dm_mod hid_generic usbhid hid sd_mod ahci libahci xhci_pci crct10dif_pclmul crc32_pclmul xhci_hcd crc32c_intel libata megaraid_sas ghash_clmulni_intel usbcore scsi_mod igb sha512_ssse3 sha256_ssse3 i2c_i801 i2c_algo_bit i2c_smbus sha1_ssse3 usb_common dca scsi_common fan video battery wmi aesni_intel gf128mul crypto_simd cryptd
2025-02-20T15:45:09.815159+01:00 srvl056 kernel: [ 851.681376] CPU: 2 UID: 0 PID: 1364 Comm: kworker/u32:1 Not tainted 6.12.9+bpo-amd64 #1 Debian 6.12.9-1~bpo12+1
2025-02-20T15:45:09.826795+01:00 srvl056 kernel: [ 851.692895] Hardware name: Intel Corporation S1200SP/S1200SP, BIOS S1200SP.86B.03.01.0049.060120200516 06/01/2020
2025-02-20T15:45:09.833054+01:00 srvl056 kernel: [ 851.704552] Workqueue: rpciod rpc_async_schedule [sunrpc]
2025-02-20T15:45:09.839019+01:00 srvl056 kernel: [ 851.710783] RIP: 0010:nfsd4_cb_done+0x4e5/0x550 [nfsd]
2025-02-20T15:45:09.860121+01:00 srvl056 kernel: [ 851.716738] Code: 8b 33 45 89 fe e9 d1 fb ff ff 80 3d 77 d7 01 00 00 0f 85 f3 fb ff ff 48 c7 c7 06 6b e0 c0 c6 05 63 d7 01 00 01 e8 9b 01 53 f6 <0f> 0b 8b 73 54 e9 d6 fb ff ff 0f 1f 44 00 00 e9 59 fd ff ff 41 89
2025-02-20T15:45:09.866189+01:00 srvl056 kernel: [ 851.737918] RSP: 0018:ffffa50f81287dc8 EFLAGS: 00010282
2025-02-20T15:45:09.874304+01:00 srvl056 kernel: [ 851.743915] RAX: 0000000000000000 RBX: ffff8b26707190f0 RCX: 0000000000000027
2025-02-20T15:45:09.882419+01:00 srvl056 kernel: [ 851.752031] RDX: ffff8b2da1321788 RSI: 0000000000000001 RDI: ffff8b2da1321780
2025-02-20T15:45:09.890522+01:00 srvl056 kernel: [ 851.760132] RBP: ffff8b264af1ba18 R08: 0000000000000000 R09: 0000000000000003
2025-02-20T15:45:09.898624+01:00 srvl056 kernel: [ 851.768234] R10: ffffa50f81287c58 R11: ffff8b2da4ffffe8 R12: ffff8b264af1ba18
2025-02-20T15:45:09.906742+01:00 srvl056 kernel: [ 851.776355] R13: ffff8b264b5a0d00 R14: 0000000000000001 R15: ffff8b26812f6e00
2025-02-20T15:45:09.915943+01:00 srvl056 kernel: [ 851.784473] FS: 0000000000000000(0000) GS:ffff8b2da1300000(0000) knlGS:0000000000000000
2025-02-20T15:45:09.922529+01:00 srvl056 kernel: [ 851.793698] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2025-02-20T15:45:09.930692+01:00 srvl056 kernel: [ 851.800294] CR2: 000000c000bed000 CR3: 0000000852622005 CR4: 00000000003706f0
2025-02-20T15:45:09.938810+01:00 srvl056 kernel: [ 851.808423] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
2025-02-20T15:45:09.946926+01:00 srvl056 kernel: [ 851.816524] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
2025-02-20T15:45:09.949822+01:00 srvl056 kernel: [ 851.824655] Call Trace:
2025-02-20T15:45:09.956035+01:00 srvl056 kernel: [ 851.827545] <TASK>
2025-02-20T15:45:09.956040+01:00 srvl056 kernel: [ 851.830008] ? __warn+0x89/0x130
2025-02-20T15:45:09.961265+01:00 srvl056 kernel: [ 851.833742] ? nfsd4_cb_done+0x4e5/0x550 [nfsd]
2025-02-20T15:45:09.965545+01:00 srvl056 kernel: [ 851.839009] ? report_bug+0x164/0x190
2025-02-20T15:45:09.969967+01:00 srvl056 kernel: [ 851.843262] ? prb_read_valid+0x1b/0x30
2025-02-20T15:45:09.973989+01:00 srvl056 kernel: [ 851.847674] ? handle_bug+0x58/0x90
2025-02-20T15:45:09.978406+01:00 srvl056 kernel: [ 851.851688] ? exc_invalid_op+0x17/0x70
2025-02-20T15:45:09.983227+01:00 srvl056 kernel: [ 851.856136] ? asm_exc_invalid_op+0x1a/0x20
2025-02-20T15:45:09.988458+01:00 srvl056 kernel: [ 851.860937] ? nfsd4_cb_done+0x4e5/0x550 [nfsd]
2025-02-20T15:45:09.993695+01:00 srvl056 kernel: [ 851.866186] ? nfsd4_cb_done+0x4e5/0x550 [nfsd]
2025-02-20T15:45:09.999502+01:00 srvl056 kernel: [ 851.871405] ? __pfx_rpc_exit_task+0x10/0x10 [sunrpc]
2025-02-20T15:45:10.004636+01:00 srvl056 kernel: [ 851.877231] rpc_exit_task+0x5f/0x180 [sunrpc]
2025-02-20T15:45:10.009771+01:00 srvl056 kernel: [ 851.882381] __rpc_execute+0xb5/0x490 [sunrpc]
2025-02-20T15:45:10.015330+01:00 srvl056 kernel: [ 851.887528] rpc_async_schedule+0x2f/0x40 [sunrpc]
2025-02-20T15:45:10.019940+01:00 srvl056 kernel: [ 851.893041] process_one_work+0x179/0x390
2025-02-20T15:45:10.024317+01:00 srvl056 kernel: [ 851.897737] worker_thread+0x251/0x360
2025-02-20T15:45:10.029242+01:00 srvl056 kernel: [ 851.902054] ? __pfx_worker_thread+0x10/0x10
2025-02-20T15:45:10.032907+01:00 srvl056 kernel: [ 851.907009] kthread+0xcf/0x100
2025-02-20T15:45:10.037243+01:00 srvl056 kernel: [ 851.910643] ? __pfx_kthread+0x10/0x10
2025-02-20T15:45:10.041362+01:00 srvl056 kernel: [ 851.914955] ret_from_fork+0x31/0x50
2025-02-20T15:45:10.045701+01:00 srvl056 kernel: [ 851.919102] ? __pfx_kthread+0x10/0x10
2025-02-20T15:45:10.050219+01:00 srvl056 kernel: [ 851.923449] ret_from_fork_asm+0x1a/0x30
2025-02-20T15:45:10.052862+01:00 srvl056 kernel: [ 851.927992] </TASK>
2025-02-20T15:45:10.058171+01:00 srvl056 kernel: [ 851.930576] ---[ end trace 0000000000000000 ]---