Bug 216674
| Summary: | kernel NULL pointer dereference in vfs_setlease() | ||
|---|---|---|---|
| Product: | File System | Reporter: | a1bert (a1bert) |
| Component: | NFS | Assignee: | Chuck Lever (cel) |
| Status: | RESOLVED PATCH_ALREADY_AVAILABLE | ||
| Severity: | normal | CC: | jlayton |
| Priority: | P1 | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Kernel Version: | 6.0.x | Subsystem: | |
| Regression: | No | Bisected commit-id: | |
| Attachments: | trace-cmd record -e nfsd -e sunrpc | ||
|
Description
a1bert
2022-11-08 21:55:07 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.
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. (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? 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 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. 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 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.
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
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. 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. |