Bug 216674 - kernel NULL pointer dereference in vfs_setlease()
Summary: kernel NULL pointer dereference in vfs_setlease()
Status: RESOLVED PATCH_ALREADY_AVAILABLE
Alias: None
Product: File System
Classification: Unclassified
Component: NFS (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Chuck Lever
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2022-11-08 21:55 UTC by a1bert
Modified: 2023-03-09 15:08 UTC (History)
1 user (show)

See Also:
Kernel Version: 6.0.x
Subsystem:
Regression: No
Bisected commit-id:


Attachments
trace-cmd record -e nfsd -e sunrpc (1.32 MB, application/x-xz)
2022-11-30 07:01 UTC, a1bert
Details

Description a1bert 2022-11-08 21:55:07 UTC
after upgrade from 5.19.11 to 6.0.6,6.0.7 I am experiencing this when mounting nfs exported xfs & btrfs filesystems





[112807.471573] BUG: kernel NULL pointer dereference, address: 00000000000000d0
[112807.471590] #PF: supervisor read access in kernel mode
[112807.471595] #PF: error_code(0x0000) - not-present page
[112807.471599] PGD 0 P4D 0 
[112807.471605] Oops: 0000 [#1] PREEMPT SMP NOPTI
[112807.471611] CPU: 1 PID: 2156 Comm: nfsd Tainted: G     U  W          6.0.7-060007-generic #202211031652
[112807.471618] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./J4105M, BIOS L1.99 12/31/2019
[112807.471622] RIP: 0010:vfs_setlease+0x2b/0x90
[112807.471633] Code: 1f 44 00 00 55 48 89 e5 41 55 49 89 fd 53 48 89 d3 48 83 ec 10 48 85 d2 74 06 48 83 fe 02 75 30 49 8b 45 28 48 89 da 4c 89 ef <48> 8b 80 d0 00 00 00 48 85 c0 74 3b ff d0 0f 1f 00 48 83 c4 10 5b
[112807.471641] RSP: 0018:ffffb275c2313c90 EFLAGS: 00010246
[112807.471646] RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffffb275c2313cc0
[112807.471650] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffffa0b20539faa8
[112807.471654] RBP: ffffb275c2313cb0 R08: 0000000000000000 R09: 0000000000000000
[112807.471659] R10: 0000000000000000 R11: 0000000000000000 R12: ffffa0b20aa80ab0
[112807.471663] R13: ffffa0b20539faa8 R14: ffffa0b216def5e0 R15: ffffa0b2140d0c00
[112807.471668] FS:  0000000000000000(0000) GS:ffffa0b56fc80000(0000) knlGS:0000000000000000
[112807.471673] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[112807.471677] CR2: 00000000000000d0 CR3: 00000002f2e10000 CR4: 0000000000352ee0
[112807.471682] Call Trace:
[112807.471686]  <TASK>
[112807.471694]  ? nfsd4_cld_remove+0x18a/0x200 [nfsd]
[112807.471757]  destroy_unhashed_deleg+0x6d/0x100 [nfsd]
[112807.471803]  __destroy_client+0xdd/0x250 [nfsd]
[112807.471846]  expire_client+0x63/0x80 [nfsd]
[112807.471887]  nfsd4_create_session+0x8d6/0xaf0 [nfsd]
[112807.471929]  nfsd4_proc_compound+0x3b5/0x770 [nfsd]
[112807.472001]  nfsd_dispatch+0x174/0x2a0 [nfsd]
[112807.472076]  svc_process_common+0x2a8/0x640 [sunrpc]
[112807.472204]  ? svc_handle_xprt+0x18d/0x370 [sunrpc]
[112807.472269]  ? nfsd_svc+0x1b0/0x1b0 [nfsd]
[112807.472311]  ? nfsd_shutdown_threads+0xb0/0xb0 [nfsd]
[112807.472352]  svc_process+0xba/0x110 [sunrpc]
[112807.472413]  nfsd+0xdc/0x1b0 [nfsd]
[112807.472453]  kthread+0xe6/0x110
[112807.472463]  ? kthread_complete_and_exit+0x20/0x20
[112807.472470]  ret_from_fork+0x1f/0x30
[112807.472478]  </TASK>
[112807.472480] Modules linked in: rpcsec_gss_krb5 tls xt_conntrack xt_MASQUERADE xfrm_user xfrm_algo xt_addrtype nft_compat veth vhost_net vhost vhost_iotlb tap wireguard curve25519_x86_64 libchacha20poly1305 chacha_x86_64 poly1305_x86_64 libcurve25519_generic libchacha ip6_udp_tunnel udp_tunnel lz4 lz4_compress z3fold bridge snd_sof_pci_intel_apl snd_sof_intel_hda_common nls_iso8859_1 soundwire_intel soundwire_generic_allocation soundwire_cadence xfs snd_sof_intel_hda snd_sof_pci snd_sof_xtensa_dsp snd_sof snd_sof_utils soundwire_bus ir_nec_decoder rc_astrometa_t2hybrid snd_soc_avs snd_soc_hda_codec snd_soc_skl snd_soc_hdac_hda rtl2832_sdr snd_hda_ext_core snd_soc_sst_ipc snd_soc_sst_dsp videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 snd_soc_acpi_intel_match videobuf2_common snd_soc_acpi videodev snd_soc_core snd_compress r820t snd_hda_codec_hdmi intel_pmc_bxt mn88473 ac97_bus intel_telemetry_pltdrv rtl2832 intel_punit_ipc ir_rc5_decoder snd_hda_codec_realtek intel_telemetry_core
[112807.472596]  snd_pcm_dmaengine snd_hda_codec_generic si2157 x86_pkg_temp_thermal intel_powerclamp ledtrig_audio rc_dvbsky kvm_intel snd_hda_intel si2168 snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec mei_pxp mei_hdcp ppdev snd_hda_core dvb_usb_rtl28xxu ts2020 kvm snd_hwdep intel_rapl_msr dvb_usb_dvbsky dvb_usb_v2 snd_pcm smipcie snd_timer m88ds3103 i2c_mux ch341 snd usbserial dvb_core processor_thermal_device_pci_legacy processor_thermal_device processor_thermal_rfim mc rapl input_leds intel_cstate soundcore processor_thermal_mbox mei_me processor_thermal_rapl serio_raw ee1004 intel_rapl_common mei intel_soc_dts_iosf parport_pc int3400_thermal int3403_thermal int340x_thermal_zone int3406_thermal mac_hid dptf_power parport acpi_thermal_rel nft_nat nft_masq nft_chain_nat nf_nat nf_log_syslog nft_log sch_fq_codel nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 8021q garp mrp stp llc nf_tables nct6775 nct6775_core nfsd dm_multipath hwmon_vid nfnetlink wmi scsi_dh_rdac scsi_dh_emc
[112807.472810]  scsi_dh_alua coretemp auth_rpcgss nfs_acl lockd grace sunrpc ramoops reed_solomon efi_pstore pstore_blk pstore_zone ip_tables x_tables autofs4 btrfs blake2b_generic zstd_compress raid10 multipath linear raid0 dm_raid raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 i915 i2c_algo_bit drm_buddy ttm drm_display_helper crct10dif_pclmul crc32_pclmul cec rc_core drm_kms_helper syscopyarea sysfillrect polyval_generic sysimgblt fb_sys_fops i2c_i801 ghash_clmulni_intel aesni_intel crypto_simd cryptd i2c_smbus drm r8169 xhci_pci ahci xhci_pci_renesas realtek libahci video pinctrl_geminilake
[112807.472925] CR2: 00000000000000d0
[112807.472930] ---[ end trace 0000000000000000 ]---
[112807.605087] RIP: 0010:vfs_setlease+0x2b/0x90
[112807.605107] Code: 1f 44 00 00 55 48 89 e5 41 55 49 89 fd 53 48 89 d3 48 83 ec 10 48 85 d2 74 06 48 83 fe 02 75 30 49 8b 45 28 48 89 da 4c 89 ef <48> 8b 80 d0 00 00 00 48 85 c0 74 3b ff d0 0f 1f 00 48 83 c4 10 5b
[112807.605116] RSP: 0018:ffffb275c2313c90 EFLAGS: 00010246
[112807.605121] RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffffb275c2313cc0
[112807.605126] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffffa0b20539faa8
[112807.605130] RBP: ffffb275c2313cb0 R08: 0000000000000000 R09: 0000000000000000
[112807.605135] R10: 0000000000000000 R11: 0000000000000000 R12: ffffa0b20aa80ab0
[112807.605139] R13: ffffa0b20539faa8 R14: ffffa0b216def5e0 R15: ffffa0b2140d0c00
[112807.605144] FS:  0000000000000000(0000) GS:ffffa0b56fc80000(0000) knlGS:0000000000000000
[112807.605149] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[112807.605153] CR2: 00000000000000d0 CR3: 0000000106344000 CR4: 0000000000352ee0


[263384.355406] BUG: kernel NULL pointer dereference, address: 0000000000000028
[263384.355422] #PF: supervisor read access in kernel mode
[263384.355427] #PF: error_code(0x0000) - not-present page
[263384.355431] PGD 0 P4D 0 
[263384.355437] Oops: 0000 [#1] PREEMPT SMP NOPTI
[263384.355443] CPU: 3 PID: 2226 Comm: nfsd Tainted: G     U             6.0.7-060007-generic #202211031652
[263384.355449] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./J4105M, BIOS L1.99 12/31/2019
[263384.355454] RIP: 0010:vfs_setlease+0x21/0x90
[263384.355464] Code: 19 fe ff ff e8 c0 6e a5 00 0f 1f 44 00 00 55 48 89 e5 41 55 49 89 fd 53 48 89 d3 48 83 ec 10 48 85 d2 74 06 48 83 fe 02 75 30 <49> 8b 45 28 48 89 da 4c 89 ef 48 8b 80 d0 00 00 00 48 85 c0 74 3b
[263384.355472] RSP: 0018:ffff9668424e7c90 EFLAGS: 00010246
[263384.355477] RAX: ffff8a17ca7da8f0 RBX: 0000000000000000 RCX: ffff9668424e7cc0
[263384.355481] RDX: 0000000000000000 RSI: 0000000000000002 RDI: 0000000000000000
[263384.355485] RBP: ffff9668424e7cb0 R08: 0000000000000000 R09: 0000000000000000
[263384.355490] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8a18f1704ab0
[263384.355494] R13: 0000000000000000 R14: ffff8a17d8bb6160 R15: ffff8a17dd2de000
[263384.355499] FS:  0000000000000000(0000) GS:ffff8a1b2fd80000(0000) knlGS:0000000000000000
[263384.355504] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[263384.355507] CR2: 0000000000000028 CR3: 00000002e5210000 CR4: 0000000000352ee0
[263384.355513] Call Trace:
[263384.355517]  <TASK>
[263384.355526]  ? nfsd4_cld_remove+0x18a/0x200 [nfsd]
[263384.355582]  destroy_unhashed_deleg+0x6d/0x100 [nfsd]
[263384.355630]  __destroy_client+0xdd/0x250 [nfsd]
[263384.355672]  expire_client+0x63/0x80 [nfsd]
[263384.355712]  nfsd4_create_session+0x8d6/0xaf0 [nfsd]
[263384.355754]  nfsd4_proc_compound+0x3b5/0x770 [nfsd]
[263384.355798]  nfsd_dispatch+0x174/0x2a0 [nfsd]
[263384.355841]  svc_process_common+0x2a8/0x640 [sunrpc]
[263384.355915]  ? svc_handle_xprt+0x18d/0x370 [sunrpc]
[263384.355980]  ? nfsd_svc+0x1b0/0x1b0 [nfsd]
[263384.356022]  ? nfsd_shutdown_threads+0xb0/0xb0 [nfsd]
[263384.356062]  svc_process+0xba/0x110 [sunrpc]
[263384.356124]  nfsd+0xdc/0x1b0 [nfsd]
[263384.356165]  kthread+0xe6/0x110
[263384.356174]  ? kthread_complete_and_exit+0x20/0x20
[263384.356181]  ret_from_fork+0x1f/0x30
[263384.356189]  </TASK>
[263384.356192] Modules linked in: bluetooth ecdh_generic ecc msr rpcsec_gss_krb5 tls xt_conntrack xt_MASQUERADE xfrm_user xfrm_algo xt_addrtype nft_compat veth vhost_net vhost vhost_iotlb tap wireguard curve25519_x86_64 libchacha20poly1305 chacha_x86_64 poly1305_x86_64 libcurve25519_generic libchacha ip6_udp_tunnel udp_tunnel lz4 lz4_compress z3fold bridge xfs snd_sof_pci_intel_apl snd_sof_intel_hda_common soundwire_intel soundwire_generic_allocation soundwire_cadence snd_sof_intel_hda snd_sof_pci snd_sof_xtensa_dsp ir_nec_decoder nls_iso8859_1 rc_astrometa_t2hybrid snd_sof rtl2832_sdr snd_sof_utils videobuf2_vmalloc soundwire_bus videobuf2_memops videobuf2_v4l2 videobuf2_common snd_soc_avs snd_soc_hda_codec videodev snd_soc_skl snd_soc_hdac_hda snd_hda_ext_core snd_soc_sst_ipc r820t snd_soc_sst_dsp snd_hda_codec_hdmi snd_soc_acpi_intel_match mn88473 ir_rc5_decoder rtl2832 snd_hda_codec_realtek rc_dvbsky intel_pmc_bxt snd_soc_acpi intel_telemetry_pltdrv intel_punit_ipc intel_telemetry_core
[263384.356279]  si2157 snd_soc_core x86_pkg_temp_thermal snd_hda_codec_generic intel_powerclamp snd_compress si2168 kvm_intel ac97_bus ppdev ts2020 snd_pcm_dmaengine ledtrig_audio kvm snd_hda_intel intel_rapl_msr snd_intel_dspcfg mei_hdcp mei_pxp snd_intel_sdw_acpi dvb_usb_rtl28xxu dvb_usb_dvbsky smipcie snd_hda_codec dvb_usb_v2 snd_hda_core m88ds3103 snd_hwdep ch341 dvb_core i2c_mux snd_pcm usbserial processor_thermal_device_pci_legacy mc processor_thermal_device rapl processor_thermal_rfim intel_cstate parport_pc input_leds processor_thermal_mbox processor_thermal_rapl snd_timer mei_me int3406_thermal intel_rapl_common snd mei dptf_power intel_soc_dts_iosf serio_raw soundcore ee1004 int3403_thermal mac_hid int3400_thermal parport int340x_thermal_zone acpi_thermal_rel nft_nat nft_masq nft_chain_nat nf_nat nf_log_syslog nft_log nft_ct nf_conntrack nf_defrag_ipv6 sch_fq_codel nf_defrag_ipv4 8021q nf_tables garp dm_multipath mrp stp llc nfnetlink nct6775 nfsd scsi_dh_rdac nct6775_core
[263384.356399]  scsi_dh_emc scsi_dh_alua auth_rpcgss hwmon_vid wmi nfs_acl lockd coretemp grace ramoops pstore_blk reed_solomon efi_pstore sunrpc pstore_zone ip_tables x_tables autofs4 btrfs blake2b_generic zstd_compress raid10 multipath linear raid0 dm_raid raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 i915 crct10dif_pclmul crc32_pclmul i2c_algo_bit drm_buddy ttm drm_display_helper polyval_generic ghash_clmulni_intel cec r8169 aesni_intel rc_core drm_kms_helper syscopyarea sysfillrect crypto_simd sysimgblt fb_sys_fops ahci xhci_pci drm i2c_i801 cryptd xhci_pci_renesas realtek i2c_smbus libahci video pinctrl_geminilake
[263384.356511] CR2: 0000000000000028
[263384.356516] ---[ end trace 0000000000000000 ]---
[263384.548316] RIP: 0010:vfs_setlease+0x21/0x90
[263384.548353] Code: 19 fe ff ff e8 c0 6e a5 00 0f 1f 44 00 00 55 48 89 e5 41 55 49 89 fd 53 48 89 d3 48 83 ec 10 48 85 d2 74 06 48 83 fe 02 75 30 <49> 8b 45 28 48 89 da 4c 89 ef 48 8b 80 d0 00 00 00 48 85 c0 74 3b
[263384.548375] RSP: 0018:ffff9668424e7c90 EFLAGS: 00010246
[263384.548390] RAX: ffff8a17ca7da8f0 RBX: 0000000000000000 RCX: ffff9668424e7cc0
[263384.548402] RDX: 0000000000000000 RSI: 0000000000000002 RDI: 0000000000000000
[263384.548413] RBP: ffff9668424e7cb0 R08: 0000000000000000 R09: 0000000000000000
[263384.548425] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8a18f1704ab0
[263384.548436] R13: 0000000000000000 R14: ffff8a17d8bb6160 R15: ffff8a17dd2de000
[263384.548448] FS:  0000000000000000(0000) GS:ffff8a1b2fd80000(0000) knlGS:0000000000000000
[263384.548462] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[263384.548472] CR2: 0000000000000028 CR3: 000000012017c000 CR4: 0000000000352ee0
Comment 1 Jeff Layton 2022-11-08 23:17:33 UTC
On my kernel:

(gdb) list *(vfs_setlease+0x2b)
0xffffffff81640d7b is in vfs_setlease (fs/locks.c:1972).
1967	int
1968	vfs_setlease(struct file *filp, long arg, struct file_lock **lease, void **priv)
1969	{
1970		if (lease)
1971			setlease_notifier(arg, *lease);
1972		if (filp->f_op->setlease)
1973			return filp->f_op->setlease(filp, arg, lease, priv);
1974		else
1975			return generic_setlease(filp, arg, lease, priv);
1976	}

...so my guess is that filp was a NULL pointer here or something close to it. Possibly this will also be fixed by the filecache fixes that are currently sitting in linux-next.
Comment 2 Chuck Lever 2022-11-08 23:26:15 UTC
I agree @filp is probably not valid or NULL.

It's interesting that the crash appears to be happening while the server is purging a previous lease (probably courtesy state). I'm wondering why the file was closed and removed while there was still valid lease state.
Comment 3 Chuck Lever 2022-11-09 14:00:22 UTC
(In reply to a1bert from comment #0)
> after upgrade from 5.19.11 to 6.0.6,6.0.7 I am experiencing this when
> mounting nfs exported xfs & btrfs filesystems

Can you say a little more about your usage scenario? Any more you can tell us will help us find a reproducer -- I'd like to confirm that subsequent changes in this area will address this crash.

For example, did the client that is remounting crash or was there a network partition, or did the client cleanly unmount the server? How long was the time between when the client previously contacted the server and when it tried to mount again? Can you characterize the workload on the client that triggered the crash?
Comment 4 a1bert 2022-11-09 14:28:47 UTC
client triggering this bud is my ubuntu 20.04 workstation that is mounting several directories from server "sopa" at boot, it's started at morning and powered off at evening every day. 

dirs exported from server sopa are btrfs subvolumes + xfs lvm volume and are mounted from several clientes (RPis, windows clients, linuxes etc)


from workstation:

mount | grep nfs
sopa:/mnt/raid1 on /mnt/sopa type nfs4 (ro,relatime,sync,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,acregmin=0,acregmax=0,acdirmin=0,acdirmax=0,hard,noac,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=172.16.1.2,local_lock=none,addr=172.16.1.254)
sopa:/data/media on /mnt/media type nfs4 (rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=172.16.1.2,local_lock=none,addr=172.16.1.254)
sopa:/data/motion on /mnt/sopa/motion type nfs4 (ro,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=172.16.1.2,local_lock=none,addr=172.16.1.254)
sopa:/data/motion/tmp on /mnt/sopa/motion/tmp type nfs4 (ro,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=172.16.1.2,local_lock=none,addr=172.16.1.254)

journalctl | grep  /mnt/sopa (watch for Failed)

lis 04 23:14:16 fm-jn systemd[1]: Unmounting /mnt/sopa/motion/tmp...
lis 04 23:14:16 fm-jn systemd[1]: Unmounted /mnt/sopa/motion/tmp.
lis 04 23:14:16 fm-jn systemd[1]: Unmounting /mnt/sopa/motion...
lis 04 23:14:16 fm-jn systemd[1]: Unmounted /mnt/sopa/motion.
lis 04 23:14:16 fm-jn systemd[1]: Unmounting /mnt/sopa...
lis 04 23:14:27 fm-jn systemd[1]: Unmounted /mnt/sopa.
lis 05 06:15:44 fm-jn systemd[1]: Mounting /mnt/sopa...
lis 05 06:17:15 fm-jn systemd[1]: Failed to mount /mnt/sopa.
lis 05 06:17:15 fm-jn systemd[1]: Dependency failed for /mnt/sopa/motion/tmp.
lis 05 06:17:15 fm-jn systemd[1]: Dependency failed for /mnt/sopa/motion.
lis 06 16:14:02 fm-jn systemd[1]: Mounting /mnt/sopa...
lis 06 16:14:02 fm-jn systemd[1]: Mounted /mnt/sopa.
lis 06 16:14:02 fm-jn systemd[1]: Mounting /mnt/sopa/motion...
lis 06 16:14:03 fm-jn systemd[1]: Mounted /mnt/sopa/motion.
lis 06 16:14:03 fm-jn systemd[1]: mnt-sopa-motion-tmp.mount: Directory /mnt/sopa/motion/tmp to mount over is not empty, mounting anyway.
lis 06 16:14:03 fm-jn systemd[1]: Mounting /mnt/sopa/motion/tmp...
lis 06 16:14:03 fm-jn systemd[1]: Mounted /mnt/sopa/motion/tmp.
lis 06 22:15:35 fm-jn systemd[1]: Unmounting /mnt/sopa/motion/tmp...
lis 06 22:15:35 fm-jn systemd[1]: Unmounted /mnt/sopa/motion/tmp.
lis 06 22:15:35 fm-jn systemd[1]: Unmounting /mnt/sopa/motion...
lis 06 22:15:35 fm-jn systemd[1]: Unmounted /mnt/sopa/motion.
lis 06 22:15:35 fm-jn systemd[1]: Unmounting /mnt/sopa...
lis 06 22:15:36 fm-jn systemd[1]: Unmounted /mnt/sopa.
lis 07 07:10:54 fm-jn systemd[1]: Mounting /mnt/sopa...
lis 07 07:10:55 fm-jn systemd[1]: Mounted /mnt/sopa.
lis 07 07:10:55 fm-jn systemd[1]: Mounting /mnt/sopa/motion...
lis 07 07:10:55 fm-jn systemd[1]: Mounted /mnt/sopa/motion.
lis 07 07:10:55 fm-jn systemd[1]: mnt-sopa-motion-tmp.mount: Directory /mnt/sopa/motion/tmp to mount over is not empty, mounting anyway.
lis 07 07:10:55 fm-jn systemd[1]: Mounting /mnt/sopa/motion/tmp...
lis 07 07:10:55 fm-jn systemd[1]: Mounted /mnt/sopa/motion/tmp.
lis 07 23:13:56 fm-jn systemd[1]: Unmounting /mnt/sopa/motion/tmp...
lis 07 23:13:56 fm-jn systemd[1]: Unmounted /mnt/sopa/motion/tmp.
lis 07 23:13:56 fm-jn systemd[1]: Unmounting /mnt/sopa/motion...
lis 07 23:13:56 fm-jn systemd[1]: Unmounted /mnt/sopa/motion.
lis 07 23:13:56 fm-jn systemd[1]: Unmounting /mnt/sopa...
lis 07 23:14:06 fm-jn systemd[1]: Unmounted /mnt/sopa.
lis 08 07:54:53 fm-jn systemd[1]: Mounting /mnt/sopa...
lis 08 07:56:23 fm-jn systemd[1]: Failed to mount /mnt/sopa.
lis 08 07:56:23 fm-jn systemd[1]: Dependency failed for /mnt/sopa/motion.
lis 08 07:56:23 fm-jn systemd[1]: Dependency failed for /mnt/sopa/motion/tmp.
lis 09 00:08:10 fm-jn systemd[1]: Unmounting /mnt/sopa/motion/tmp...
lis 09 00:08:11 fm-jn systemd[1]: Unmounted /mnt/sopa/motion/tmp.
lis 09 00:08:11 fm-jn systemd[1]: Unmounting /mnt/sopa/motion...
lis 09 00:08:11 fm-jn systemd[1]: Unmounted /mnt/sopa/motion.
lis 09 00:08:11 fm-jn systemd[1]: Unmounting /mnt/sopa...
lis 09 00:08:11 fm-jn systemd[1]: Unmounted /mnt/sopa.
lis 09 07:46:43 fm-jn systemd[1]: Mounting /mnt/sopa...
lis 09 07:46:44 fm-jn systemd[1]: Mounted /mnt/sopa.
lis 09 07:46:44 fm-jn systemd[1]: Mounting /mnt/sopa/motion...
lis 09 07:46:44 fm-jn systemd[1]: Mounted /mnt/sopa/motion.
lis 09 07:46:44 fm-jn systemd[1]: mnt-sopa-motion-tmp.mount: Directory /mnt/sopa/motion/tmp to mount over is not empty, mounting anyway.
lis 09 07:46:44 fm-jn systemd[1]: Mounting /mnt/sopa/motion/tmp...
lis 09 07:46:44 fm-jn systemd[1]: Mounted /mnt/sopa/motion/tmp.


Nov  8 07:54:53 sopa rpc.mountd[1761]: v4.2 client attached: 0x903bbb506365f893 from "172.16.1.2:682"
Nov  8 07:54:53 sopa kernel: [263384.355406] BUG: kernel NULL pointer dereference, address: 0000000000000028
Nov  8 07:54:53 sopa kernel: [263384.355422] #PF: supervisor read access in kernel mode
Nov  8 07:54:53 sopa kernel: [263384.355427] #PF: error_code(0x0000) - not-present page
Nov  8 07:54:53 sopa kernel: [263384.355431] PGD 0 P4D 0 
Nov  8 07:54:53 sopa kernel: [263384.355437] Oops: 0000 [#1] PREEMPT SMP NOPTI
Nov  8 07:54:53 sopa kernel: [263384.355443] CPU: 3 PID: 2226 Comm: nfsd Tainted: G     U             6.0.7-060007-generic #202211031652
Nov  8 07:54:53 sopa kernel: [263384.355449] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./J4105M, BIOS L1.99 12/31/2019
Nov  8 07:54:53 sopa kernel: [263384.355454] RIP: 0010:vfs_setlease+0x21/0x90
Nov  8 07:54:53 sopa kernel: [263384.355464] Code: 19 fe ff ff e8 c0 6e a5 00 0f 1f 44 00 00 55 48 89 e5 41 55 49 89 fd 53 48 89 d3 48 83 ec 10 48 85 d2 74




from server:
root@sopa:~# uname  -a
Linux sopa 6.0.7-060007-generic #202211031652 SMP PREEMPT_DYNAMIC Thu Nov 3 18:33:21 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
#from https://kernel.ubuntu.com/~kernel-ppa/mainline/?C=N;O=D

@sopa:~# mount  | grep data
/dev/mapper/sopa-motion on /data/motion type xfs (rw,noatime,attr2,inode64,logbufs=8,logbsize=32k,sunit=128,swidth=256,noquota)
none on /data/motion/tmp type tmpfs (rw,relatime,inode64)
/dev/sdb3 on /data/sopa type btrfs (rw,noatime,compress=zstd:15,space_cache,skip_balance,subvolid=8323,subvol=/sopa)
/dev/sdb3 on /data/nfs type btrfs (rw,noatime,compress=zstd:15,space_cache,skip_balance,subvolid=1021,subvol=/nfs)
/dev/sdb3 on /data/lxc type btrfs (rw,noatime,compress=zstd:15,space_cache,skip_balance,subvolid=9264,subvol=/lxc)
/dev/sdb3 on /data/tftp type btrfs (rw,noatime,compress=zstd:15,space_cache,skip_balance,subvolid=8164,subvol=/tftp)
/dev/sdb3 on /data/libvirt type btrfs (rw,noatime,compress=zstd:15,space_cache,skip_balance,subvolid=8126,subvol=/libvirt)
/dev/sdb3 on /data/www type btrfs (rw,noatime,compress=zstd:15,space_cache,skip_balance,subvolid=8163,subvol=/www)
/dev/sdb3 on /data/media type btrfs (rw,noatime,compress=zstd:15,space_cache,skip_balance,subvolid=8165,subvol=/media)
/dev/sdb3 on /data/backup type btrfs (rw,noatime,compress=zstd:15,space_cache,skip_balance,subvolid=8322,subvol=/backup)

root@sopa:~# showmount  -e
Export list for sopa:
/data/backup/data/fotky        172.16.1.0/24
/data/nfs/users/jn             172.16.1.0/24
/data/nfs/loto1                172.16.1.0/24
/data/nfs/raspbian-buster      172.16.1.0/24
/data/nfs/clonezilla           172.16.1.0/24
/data/nfs/opipc                172.16.1.0/24
/data/nfs/krimartv             172.16.1.0/24
/data/nfs/tom                  172.16.1.0/24
/data/nfs/tvobyvak             172.16.1.0/24
/data/motion                   172.16.1.2
/data/motion/tmp               172.16.1.2
/data/lxc                      172.16.1.2
/mnt/raid1                     172.16.1.2
/data/media                    172.16.1.0/24
/data/nfs/nexx                 172.16.1.103
/data/nfs/tvloznice            172.16.1.221
/data/nfs/nilan                172.16.1.242
Comment 5 Chuck Lever 2022-11-09 14:55:34 UTC
It appears that the client is unmounting cleanly, so there should be no remaining open file state. I assume you reboot your NFS server after each crash?

Can you try the following: Before mounting your client in the morning, go to the server and start tracing:

  # trace-cmd record -e nfsd -e sunrpc

Once you've done the mount and the crash occurs, ^C the trace-cmd. Attach the resulting trace.dat file to this bug report.
Comment 6 a1bert 2022-11-16 18:18:46 UTC
well I am "hunting" for "trace" of the crash since 2022-11-09 without success (bug was not triggered since that)

but today my kernel crashed at night without mount/unmount interaction from my side:




Nov 16 00:05:42 sopa kernel: [662092.283769] BUG: unable to handle page fault for address: 00000b1eb2258028
Nov 16 00:05:42 sopa kernel: [662092.283784] #PF: supervisor read access in kernel mode
Nov 16 00:05:42 sopa kernel: [662092.283789] #PF: error_code(0x0000) - not-present page
Nov 16 00:05:42 sopa kernel: [662092.283793] PGD 0 P4D 0 
Nov 16 00:05:42 sopa kernel: [662092.283800] Oops: 0000 [#1] PREEMPT SMP NOPTI
Nov 16 00:05:42 sopa kernel: [662092.283806] CPU: 2 PID: 2129 Comm: nfsd Tainted: G     U             6.0.7-060007-generic #202211031652
Nov 16 00:05:42 sopa kernel: [662092.283813] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./J4105M, BIOS L1.99 12/31/2019
Nov 16 00:05:42 sopa kernel: [662092.283818] RIP: 0010:vfs_setlease+0x21/0x90
Nov 16 00:05:42 sopa kernel: [662092.283829] Code: 19 fe ff ff e8 c0 6e a5 00 0f 1f 44 00 00 55 48 89 e5 41 55 49 89 fd 53 48 89 d3 48 83 ec 10 48 85 d2 74 06 48 83 fe 02 75 30 <49> 8b 45 28 48 89 da 4c 89 ef 48 8b 80 d0 00 00 00 48 85 c0 74 3b
Nov 16 00:05:42 sopa kernel: [662092.283837] RSP: 0018:ffffc32080c07d38 EFLAGS: 00010246
Nov 16 00:05:42 sopa kernel: [662092.283842] RAX: ffffa0c398992478 RBX: 0000000000000000 RCX: ffffc32080c07d68
Nov 16 00:05:42 sopa kernel: [662092.283847] RDX: 0000000000000000 RSI: 0000000000000002 RDI: 00000b1eb2258000
Nov 16 00:05:42 sopa kernel: [662092.283852] RBP: ffffc32080c07d58 R08: 0000000000000000 R09: 0000000000000000
Nov 16 00:05:42 sopa kernel: [662092.283856] R10: 0000000000000000 R11: 0000000000000000 R12: ffffa0c3950d8720
Nov 16 00:05:42 sopa kernel: [662092.283860] R13: 00000b1eb2258000 R14: ffffa0c3dc873700 R15: ffffffffa31abb80
Nov 16 00:05:42 sopa kernel: [662092.283865] FS:  0000000000000000(0000) GS:ffffa0c6efd00000(0000) knlGS:0000000000000000
Nov 16 00:05:42 sopa kernel: [662092.283870] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Nov 16 00:05:42 sopa kernel: [662092.283874] CR2: 00000b1eb2258028 CR3: 00000001189b6000 CR4: 0000000000352ee0
Nov 16 00:05:42 sopa kernel: [662092.283880] Call Trace:
Nov 16 00:05:42 sopa kernel: [662092.283884]  <TASK>
Nov 16 00:05:42 sopa kernel: [662092.283893]  destroy_unhashed_deleg+0x6d/0x100 [nfsd]
Nov 16 00:05:42 sopa kernel: [662092.283950]  nfsd4_delegreturn+0x137/0x140 [nfsd]
Nov 16 00:05:42 sopa kernel: [662092.283996]  nfsd4_proc_compound+0x3b5/0x770 [nfsd]
Nov 16 00:05:42 sopa kernel: [662092.284041]  nfsd_dispatch+0x174/0x2a0 [nfsd]
Nov 16 00:05:42 sopa kernel: [662092.284084]  svc_process_common+0x2a8/0x640 [sunrpc]
Nov 16 00:05:42 sopa kernel: [662092.284158]  ? svc_handle_xprt+0x18d/0x370 [sunrpc]
Nov 16 00:05:42 sopa kernel: [662092.284225]  ? nfsd_svc+0x1b0/0x1b0 [nfsd]
Nov 16 00:05:42 sopa kernel: [662092.284268]  ? nfsd_shutdown_threads+0xb0/0xb0 [nfsd]
Nov 16 00:05:42 sopa kernel: [662092.284310]  svc_process+0xba/0x110 [sunrpc]
Nov 16 00:05:42 sopa kernel: [662092.284372]  nfsd+0xdc/0x1b0 [nfsd]
Nov 16 00:05:42 sopa kernel: [662092.284413]  kthread+0xe6/0x110
Nov 16 00:05:42 sopa kernel: [662092.284420]  ? kthread_complete_and_exit+0x20/0x20
Nov 16 00:05:42 sopa kernel: [662092.284427]  ret_from_fork+0x1f/0x30
Nov 16 00:05:42 sopa kernel: [662092.284435]  </TASK>
Nov 16 00:05:42 sopa kernel: [662092.284437] Modules linked in: binfmt_misc bluetooth ecdh_generic ecc tls xt_conntrack xt_MASQUERADE xfrm_user xfrm_algo xt_addrtype nft_compat rpcsec_gss_krb5 veth vhost_net vhost vhost_iotlb tap wireguard curve25
Nov 16 00:05:42 sopa kernel: [662092.284515]  ir_rc5_decoder videobuf2_common intel_telemetry_core videodev ledtrig_audio rc_dvbsky si2157 r820t snd_hda_intel mn88473 x86_pkg_temp_thermal snd_intel_dspcfg intel_powerclamp si2168 kvm_intel rtl2832
Nov 16 00:05:42 sopa kernel: [662092.284630]  nct6775 scsi_dh_alua nct6775_core hwmon_vid nfnetlink wmi auth_rpcgss nfs_acl coretemp lockd grace sunrpc ramoops pstore_blk reed_solomon pstore_zone efi_pstore ip_tables x_tables autofs4 btrfs blake2b
Nov 16 00:05:42 sopa kernel: [662092.284746] CR2: 00000b1eb2258028
Nov 16 00:05:42 sopa kernel: [662092.284751] ---[ end trace 0000000000000000 ]---
Nov 16 00:05:42 sopa kernel: [662094.222660] RIP: 0010:vfs_setlease+0x21/0x90
Nov 16 00:05:42 sopa kernel: [662094.222683] Code: 19 fe ff ff e8 c0 6e a5 00 0f 1f 44 00 00 55 48 89 e5 41 55 49 89 fd 53 48 89 d3 48 83 ec 10 48 85 d2 74 06 48 83 fe 02 75 30 <49> 8b 45 28 48 89 da 4c 89 ef 48 8b 80 d0 00 00 00 48 85 c0 74 3b
Nov 16 00:05:42 sopa kernel: [662094.222691] RSP: 0018:ffffc32080c07d38 EFLAGS: 00010246
Nov 16 00:05:42 sopa kernel: [662094.222697] RAX: ffffa0c398992478 RBX: 0000000000000000 RCX: ffffc32080c07d68
Nov 16 00:05:42 sopa kernel: [662094.222702] RDX: 0000000000000000 RSI: 0000000000000002 RDI: 00000b1eb2258000
Nov 16 00:05:42 sopa kernel: [662094.222706] RBP: ffffc32080c07d58 R08: 0000000000000000 R09: 0000000000000000
Nov 16 00:05:42 sopa kernel: [662094.222710] R10: 0000000000000000 R11: 0000000000000000 R12: ffffa0c3950d8720
Nov 16 00:05:42 sopa kernel: [662094.222714] R13: 00000b1eb2258000 R14: ffffa0c3dc873700 R15: ffffffffa31abb80
Nov 16 00:05:42 sopa kernel: [662094.222719] FS:  0000000000000000(0000) GS:ffffa0c6efd00000(0000) knlGS:0000000000000000
Nov 16 00:05:42 sopa kernel: [662094.222725] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Comment 7 Jeff Layton 2022-11-16 19:55:43 UTC
At this point, I doubt more stack traces from old kernels will help. What would help would be to have someone suffering from this test Chuck's for-next branch, which contains a set of fixes to the filecache.

In particular, this patch, though it depends on a number of previous patches:

    f219ed0df8c4 nfsd: rework refcounting in filecache

These fixes are in linux-next too, if testing that is easier.
Comment 8 a1bert 2022-11-30 07:01:31 UTC
Created attachment 303331 [details]
trace-cmd record -e nfsd -e sunrpc

uname: 6.0.9-060009-generic #202211161102 SMP PREEMPT_DYNAMIC Wed Nov 16 12:14:18 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
Comment 9 Chuck Lever 2022-11-30 15:01:48 UTC
I see:

compound 1: EXCHANGE_ID
   clid_verf_mismatched
compound 2: EXCHANGE_ID
   clid_verf_mismatched
compound 3: does not complete, but is likely CREATE_SESSION
   clid_replaced
   clid_confirmed

Then it starts setting up the backchannel and the trace ends there.

I'm guessing that:
 - clid_replaced is the tracepoint at fs/nfsd/nfs4state.c:#3591
 - clid_confirmed is the tracepoint at fs/nfsd/nfs4state.c:#2957, called from #3593.

nfsd4_create_session() calls expire_client() on the replaced nfs4_client as it exits. __destroy_client() finds items on that client's cl_delegations list.

Here's where I'm confused: if the client unmounted cleanly the night before, there should be nothing on that list. In fact, there shouldn't be an nfs4_client structure at all: the client should have done a DESTROY_SESSION / DESTROY_CLIENTID after unmounting.

So I have to assume the client is not unmounting cleanly. Linux NFSD in v6.0 is now courteous, so the nfs4_client remains in place overnight rather than being expunged after 3 minutes.

The likely scenario is, as Jeff says, a problem with filecache refcounting that lingers because the nfs4_client is not removed. Some possible workarounds include:

1. Disable delegation on your server temporarily (google for how to do that)
2. Stick with v5.19 on your server
3. Try building from the for-next branch of https://git.kernel.org/pub/scm/linux/kernel/git/cel/linux.git

Workaround 3 would be most helpful to us, as it would confirm whether the problem is addressed by Jeff's patches.
Comment 10 Chuck Lever 2023-03-09 15:08:22 UTC
There are a number of patches that went into v6.2 that should address this issue. Many of them have been backported to v6.1.y.

Note You need to log in before you can comment on or make changes to this bug.