Bug 207464
| Summary: | Panic when destroying ZFS snapshot | ||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | Base System | Reporter: | dustinwenz | ||||||||||
| Component: | kern | Assignee: | Andriy Gapon <avg> | ||||||||||
| Status: | Closed FIXED | ||||||||||||
| Severity: | Affects Many People | CC: | avg, daniel.genis, delphij, drs-freebsd, fs, harrison, hpowell, karl, marc, matthias.pfaller, re | ||||||||||
| Priority: | --- | Keywords: | crash | ||||||||||
| Version: | 10.2-STABLE | Flags: | koobs:
mfc-stable10+
koobs: mfc-stable9+ |
||||||||||
| Hardware: | Any | ||||||||||||
| OS: | Any | ||||||||||||
| Attachments: |
|
||||||||||||
This is almost a stock kernel, with vimage enabled and the ARC patch applied from https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=187594 I see that the checkin yesterday for vfs_subr.c reverted it to back to a version from December due to an unexplained ZFS bug. It's possible this is related, but I've not been able to reproduce it yet on r295115. Turns out this is quite easy to reproduce. In the following example, the system is booted from a filesystem called "zroot". Running the following three shell commands twice in succession consistently causes a panic, even on 10.3-PRERELEASE r295115M: zfs snapshot zroot@panic ls -d /.zfs/snapshot/panic zfs destroy zroot@panic The "ls -d" operation on the .zfs snapshot is required to cause the panic. It also seems important to do this on a freshly booted system; if many successful snapshot/destroy operations are done, the machine stops being susceptible to the panic. The issue is not particularly timing-sensitive. I can still reproduce even when waiting 5 seconds between operations. In the interest of simplification, I can confirm the problem exists in stable/r296074 GENERIC, with no kernel modifications. I think this should be easy for anyone to reproduce at this point. I've confirmed the panic occurs consistently even after a clean install from the official 10.2 memstick image, using both UFS and ZFS boot on any new zpool I've created. We also get these panics (but not on the boot pool): FreeBSD nibbler 10.2-RELEASE-p9 FreeBSD 10.2-RELEASE-p9 #0: Thu Jan 14 01:32:46 UTC 2016 root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC amd64 vputx: negative ref count 0xfffff8026e11e588: tag zfs, type VDIR usecount 0, writecount 0, refcount 0 mountedhere 0 flags (VI_FREE) VI_LOCKed lock type zfs: EXCL by thread 0xfffff80dae520000 (pid 28114, zfs, tid 100862) panic: vputx: negative ref cnt cpuid = 2 KDB: stack backtrace: #0 0xffffffff80984ef0 at kdb_backtrace+0x60 #1 0xffffffff80948aa6 at vpanic+0x126 #2 0xffffffff80948973 at panic+0x43 #3 0xffffffff809eb7d5 at vputx+0x2d5 #4 0xffffffff809e4f59 at dounmount+0x689 #5 0xffffffff81a4bdd4 at zfs_unmount_snap+0x114 #6 0xffffffff81a4efc1 at zfs_ioc_destroy_snaps+0xc1 #7 0xffffffff81a4dae0 at zfsdev_ioctl+0x5f0 #8 0xffffffff80830019 at devfs_ioctl_f+0x139 #9 0xffffffff8099cde5 at kern_ioctl+0x255 #10 0xffffffff8099cae0 at sys_ioctl+0x140 #11 0xffffffff80d4b3e7 at amd64_syscall+0x357 #12 0xffffffff80d30acb at Xfast_syscall+0xfb #0 doadump (textdump=<value optimized out>) at pcpu.h:219 #1 0xffffffff80948702 in kern_reboot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:451 #2 0xffffffff80948ae5 in vpanic (fmt=<value optimized out>, ap=<value optimized out>) at /usr/src/sys/kern/kern_shutdown.c:758 #3 0xffffffff80948973 in panic (fmt=0x0) at /usr/src/sys/kern/kern_shutdown.c:687 #4 0xffffffff809eb7d5 in vputx (vp=<value optimized out>, func=<value optimized out>) at /usr/src/sys/kern/vfs_subr.c:2269 #5 0xffffffff809e4f59 in dounmount (mp=0xfffff81bc9ada000, flags=<value optimized out>, td=<value optimized out>) at /usr/src/sys/kern/vfs_mount.c:1362 #6 0xffffffff81a4bdd4 in zfs_unmount_snap (snapname=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:3484 #7 0xffffffff81a4efc1 in zfs_ioc_destroy_snaps ( poolname=0xfffffe1025f72000 "zmnt", innvl=<value optimized out>, outnvl=0xfffff804303ca740) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:3557 #8 0xffffffff81a4dae0 in zfsdev_ioctl (dev=<value optimized out>, zcmd=<value optimized out>, arg=<value optimized out>, flag=<value optimized out>, td=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:6198 #9 0xffffffff80830019 in devfs_ioctl_f (fp=0xfffff81aca04a870, com=3222821411, data=0xfffffe20260458e0, cred=<value optimized out>, td=0xfffff80dae520000) at /usr/src/sys/fs/devfs/devfs_vnops.c:785 #10 0xffffffff8099cde5 in kern_ioctl (td=0xfffff80dae520000, fd=<value optimized out>, com=0) at file.h:320 #11 0xffffffff8099cae0 in sys_ioctl (td=0xfffff80dae520000, uap=0xfffffe2026045a40) at /usr/src/sys/kern/sys_generic.c:718 #12 0xffffffff80d4b3e7 in amd64_syscall (td=0xfffff80dae520000, traced=0) at subr_syscall.c:134 #13 0xffffffff80d30acb in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:396 #14 0x0000000801a01fda in ?? () This seems to affect a fresh install of 10.3 as well. This looks like the same problem I've seen related to an automated backup for quite some time; the symptomology, if you catch it before it blows up, is that the snapshot you're trying to delete cannot be CD'd into, but it's there. If you reboot before trying to destroy it the panic does not happen, but if not, kaboom. Created attachment 169495 [details]
vmcore.txt
I've replicated this issue with a non-boot zfs filesystem on 10.3-RELEASE. zpool create foo /dev/ada1 mkdir /foo/bar zfs snapshot foo@working-copy ls -d /foo/.zfs/snapshot/working-copy/bar zfs destroy foo@working-copy Output is panic: vputx: negative ref cnt followed by a dump and reboot. I've uploaded the vmcore.txt that was generated by this bug. This bug is a major bug causing all my systems to reboot regularly, impacting production nfs servers. Thoughts for how to fix the problem are welcomed. Likely related to and fixed by this - testing as soon as I can patch. https://www.freebsd.org/security/advisories/FreeBSD-EN-16:08.zfs.asc I've put that (one-line) patch in and will see if I can trigger the panic again. Since it happens to me on a production system and I've been unable to craft a test case that makes it happen repeatedly on my test machine it may be a material amount of time before I can say it's fixed, given that the usual time-to-fail here is a week if I do not take interventions to prevent it. Interesting... I can reproduce this problem but only if I repeat the instructions twice: $ zfs snapshot foo@panic $ ls -d /foo/.zfs/snapshot/panic $ zfs destroy foo@panic ... no problem here ... $ zfs snapshot foo@panic $ ls -d /foo/.zfs/snapshot/panic $ zfs destroy foo@panic ... now it panics ... This is using a UFS root filesystem and a freshly created pool. Andy, is that WITH the one-line patch in? If so, bummer. The pattern for me here on my production machines is that during backup the machine will panic, *always* during the root filesystem backup. The system is all-ZFS and the backups are done using zfs send, after creating a snapshot (which rolls so you wind up with a duplicate of the existing file structure over time.) The system also uses timed snapshots that roll off so recovery of files is simple if they're accidentally deleted or modified without resorting to the backups. The panic is usually (but not always) preceded by a snapshot that is present, cannot be destroyed, but *also* cannot be CD'd into. Once that condition exists the following is also true: 1. If you *reboot* the box the condition is cleared and all is well; the system will *not* panic in that instance. 2. If you attempt to zfs send a stream that *includes* the "orphan" snapshot the machine will panic in dounmount (identical behavior to the traces posted here) every time. 3. You cannot zfs destroy the "rogue" snapshot that is present in the directory but cannot be cd'd into. These three things make it possible for my backup script to, most of the time, detect the panic condition on the backup run *before* the one that blows up. What I've been unable to do, however, is reproduce a test case that reliably leaves the system in the pre-panic state. Created attachment 170024 [details]
proposed patch for testing
It seems that the code has a few bugs that _almost_ cancel out each other.
Please try this patch that should eliminate those bugs.
But the fix might uncover other bugs as the FreeBSD port of zfsctl / gfs code is rather hairy. So, treat with care.
(In reply to karl from comment #14) I haven't tested the patch from the erratum, but it appears to be unrelated. I cannot get the proposed patch for testing to compile on a stock svn checkout of the 10.3 base head unless I modify VOP_UNLOCK(vp); to VOP_UNLOCK(vp, 0); in the opensolaris_vfs.c section. Compiling and testing now. (In reply to Howard Powell from comment #11) I can confirm that this seems to be unrelated. The kernel panic still occurs after updating to 10.3-RELEASE-p2 today. (In reply to Howard Powell from comment #17) Patched the 10.3-RELEASE kernel source and recompiled. A test case of creating a snapshot, reading the snapshot, then destroying the snapshot 100 times finishes without a kernel panic. Looks promising. I'm beating the hell out of the new kernel now with 5 million create-read-destroy cycles to see what happens. Andriy - can you elaborate on "It seems that the code has a few bugs that _almost_ cancel out each other." - do you mean your proposed patch or the original code had bugs? ... waiting to push a mission critical machine into production until after this is worked out. Thanks. (In reply to Howard Powell from comment #17) Thank you for the fix. I'll update the patch. (In reply to Howard Powell from comment #19) I meant the code without the patch. Created attachment 170172 [details]
proposed patch for testing
I am running the patch at the present time -- so far no panics, but my regular workload usually requires a few days (often as much as a week) before it happens. If my backup routine detects an "aw crap" (which usually comes before it goes "boom") I'll advise. A commit references this bug: Author: avg Date: Mon May 16 06:24:05 UTC 2016 New revision: 299900 URL: https://svnweb.freebsd.org/changeset/base/299900 Log: zfsctl: fix several problems with reference counts * Remove excessive references on a snapshot mountpoint vnode. zfsctl_snapdir_lookup() called VN_HOLD() on a vnode returned from zfsctl_snapshot_mknode() and the latter also had a call to VN_HOLD() on the same vnode. On top of that gfs_dir_create() already returns the vnode with the use count of 1 (set in getnewvnode). So there was 3 references on the vnode. * mount_snapshot() should keep a reference to a covered vnode. That reference is owned by the mountpoint (mounted snapshot filesystem). * Remove cryptic manipulations of a covered vnode in zfs_umount(). FreeBSD dounmount() already does the right thing and releases the covered vnode. PR: 207464 Reported by: dustinwenz@ebureau.com Tested by: Howard Powell <hpowell@lighthouseinstruments.com> MFC after: 3 weeks Changes: head/sys/cddl/compat/opensolaris/kern/opensolaris_vfs.c head/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ctldir.c head/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c Created attachment 170343 [details]
add-on patch
If you are testing the first patch could you please test this patch on top of the first patch as well?
EN candidate? Comment on attachment 170343 [details]
add-on patch
Rebuilding kernel to include this as well....
A commit references this bug: Author: avg Date: Wed Jul 13 09:14:45 UTC 2016 New revision: 302724 URL: https://svnweb.freebsd.org/changeset/base/302724 Log: MFC r299900: zfsctl: fix several problems with reference counts PR: 207464 Changes: _U stable/10/ stable/10/sys/cddl/compat/opensolaris/kern/opensolaris_vfs.c stable/10/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ctldir.c stable/10/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c A commit references this bug: Author: avg Date: Wed Jul 13 09:15:12 UTC 2016 New revision: 302725 URL: https://svnweb.freebsd.org/changeset/base/302725 Log: MFC r299900: zfsctl: fix several problems with reference counts PR: 207464 Changes: _U stable/9/sys/ stable/9/sys/cddl/compat/opensolaris/kern/opensolaris_vfs.c _U stable/9/sys/cddl/contrib/opensolaris/ stable/9/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ctldir.c stable/9/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c Correctly annotate (mfc &keywords) post-resolution This bug still affects 10.3-RELEASE and it's being triggered on a number of our machines during backups. Any chance of merging the fix to that branch in an errata notification? FreeBSD XXXXXX 10.3-RELEASE-p11 FreeBSD 10.3-RELEASE-p11 #0: Mon Oct 24 18:49:24 UTC 2016 root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC amd64 panic: vputx: negative ref cnt GNU gdb 6.1.1 [FreeBSD] Copyright 2004 Free Software Foundation, Inc. GDB is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Type "show copying" to see the conditions. There is absolutely no warranty for GDB. Type "show warranty" for details. This GDB was configured as "amd64-marcel-freebsd"... Unread portion of the kernel message buffer: panic: vputx: negative ref cnt cpuid = 3 KDB: stack backtrace: #0 0xffffffff8098e3e0 at kdb_backtrace+0x60 #1 0xffffffff809510b6 at vpanic+0x126 #2 0xffffffff80950f83 at panic+0x43 #3 0xffffffff809f78e5 at vputx+0x2d5 #4 0xffffffff809f1139 at dounmount+0x689 #5 0xffffffff81a6dfe4 at zfs_unmount_snap+0x114 #6 0xffffffff81a71301 at zfs_ioc_destroy_snaps+0xc1 #7 0xffffffff81a6fd64 at zfsdev_ioctl+0x664 #8 0xffffffff80835dc9 at devfs_ioctl_f+0x139 #9 0xffffffff809a8c85 at kern_ioctl+0x255 #10 0xffffffff809a8980 at sys_ioctl+0x140 #11 0xffffffff80d5695f at amd64_syscall+0x40f #12 0xffffffff80d3bbbb at Xfast_syscall+0xfb Uptime: 7m17s Dumping 419 out of 3995 MB:..4%..12%..23%..31%..42%..54%..61%..73%..81%..92% Reading symbols from /boot/kernel/zfs.ko.symbols...done. Loaded symbols for /boot/kernel/zfs.ko.symbols Reading symbols from /boot/kernel/opensolaris.ko.symbols...done. Loaded symbols for /boot/kernel/opensolaris.ko.symbols Reading symbols from /boot/kernel/ums.ko.symbols...done. Loaded symbols for /boot/kernel/ums.ko.symbols Reading symbols from /boot/kernel/pflog.ko.symbols...done. Loaded symbols for /boot/kernel/pflog.ko.symbols Reading symbols from /boot/kernel/pf.ko.symbols...done. Loaded symbols for /boot/kernel/pf.ko.symbols #0 doadump (textdump=<value optimized out>) at pcpu.h:219 219 pcpu.h: No such file or directory. in pcpu.h (kgdb) #0 doadump (textdump=<value optimized out>) at pcpu.h:219 #1 0xffffffff80950d12 in kern_reboot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:486 #2 0xffffffff809510f5 in vpanic (fmt=<value optimized out>, ap=<value optimized out>) at /usr/src/sys/kern/kern_shutdown.c:889 #3 0xffffffff80950f83 in panic (fmt=0x0) at /usr/src/sys/kern/kern_shutdown.c:818 #4 0xffffffff809f78e5 in vputx (vp=<value optimized out>, func=<value optimized out>) at /usr/src/sys/kern/vfs_subr.c:2348 #5 0xffffffff809f1139 in dounmount (mp=0xfffff800052da660, flags=<value optimized out>, td=<value optimized out>) at /usr/src/sys/kern/vfs_mount.c:1359 #6 0xffffffff81a6dfe4 in zfs_unmount_snap (snapname=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:3485 #7 0xffffffff81a71301 in zfs_ioc_destroy_snaps ( poolname=0xfffffe003b89b000 "hippo", innvl=<value optimized out>, outnvl=0xfffff80092925060) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:3558 #8 0xffffffff81a6fd64 in zfsdev_ioctl (dev=<value optimized out>, zcmd=<value optimized out>, arg=<value optimized out>, flag=<value optimized out>, td=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:6278 #9 0xffffffff80835dc9 in devfs_ioctl_f (fp=0xfffff8001c036230, com=3222821411, data=0xfffffe011b427a20, cred=<value optimized out>, td=0xfffff80005b3a960) at /usr/src/sys/fs/devfs/devfs_vnops.c:786 #10 0xffffffff809a8c85 in kern_ioctl (td=0xfffff80005b3a960, fd=<value optimized out>, com=0) at file.h:321 #11 0xffffffff809a8980 in sys_ioctl (td=0xfffff80005b3a960, uap=0xfffffe011b427b80) at /usr/src/sys/kern/sys_generic.c:718 #12 0xffffffff80d5695f in amd64_syscall (td=0xfffff80005b3a960, traced=0) at subr_syscall.c:141 #13 0xffffffff80d3bbbb in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:396 #14 0x0000000801a05f3a in ?? () Previous frame inner to this frame (corrupt stack?) Current language: auto; currently minimal (kgdb) I would also love to see this in the 10.3 releng branch |
FreeBSD 10.3-PRERELEASE #13 r295115M: Mon Feb 1 13:08:30 CST 2016 When destroying a ZFS snapshot of the boot filesystem, the system panicked with the message: vputx: negative ref cnt KDB stack backtrace: vputx: negative ref count 0xfffff801d7ab7b10: tag zfs, type VDIR usecount 0, writecount 0, refcount 0 mountedhere 0 flags (VI_FREE) VI_LOCKed lock type zfs: EXCL by thread 0xfffff80448797960 (pid 7211, zfs, tid 101642) panic: vputx: negative ref cnt cpuid = 13 KDB: stack backtrace: #0 0xffffffff8098f7f0 at kdb_backtrace+0x60 #1 0xffffffff80952896 at vpanic+0x126 #2 0xffffffff80952763 at panic+0x43 #3 0xffffffff809f94e5 at vputx+0x2d5 #4 0xffffffff809f2a99 at dounmount+0x689 #5 0xffffffff81a851d4 at zfs_unmount_snap+0x114 #6 0xffffffff81a884f1 at zfs_ioc_destroy_snaps+0xc1 #7 0xffffffff81a86f54 at zfsdev_ioctl+0x664 #8 0xffffffff80837469 at devfs_ioctl_f+0x139 #9 0xffffffff809aa085 at kern_ioctl+0x255 #10 0xffffffff809a9d80 at sys_ioctl+0x140 #11 0xffffffff80d68aff at amd64_syscall+0x40f #12 0xffffffff80d4dd7b at Xfast_syscall+0xfb Uptime: 4h4m41s (kgdb) bt #0 __curthread () at ./machine/pcpu.h:219 #1 doadump (textdump=<optimized out>) at /usr/src/sys/kern/kern_shutdown.c:298 #2 0xffffffff809524f2 in kern_reboot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:486 #3 0xffffffff809528d5 in vpanic (fmt=<optimized out>, ap=<optimized out>) at /usr/src/sys/kern/kern_shutdown.c:889 #4 0xffffffff80952763 in panic (fmt=<unavailable>) at /usr/src/sys/kern/kern_shutdown.c:818 #5 0xffffffff809f94e5 in vputx (vp=0xfffff801d7ab7b10, func=<optimized out>) at /usr/src/sys/kern/vfs_subr.c:2510 #6 0xffffffff809f2a99 in dounmount (mp=0xfffff80142dc4660, flags=<optimized out>, td=<optimized out>) at /usr/src/sys/kern/vfs_mount.c:1359 #7 0xffffffff81a851d4 in zfs_unmount_snap (snapname=<optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:3485 #8 0xffffffff81a884f1 in zfs_ioc_destroy_snaps (poolname=0xfffffe00170f8000 "zroot", innvl=<optimized out>, outnvl=0xfffff804488297a0) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:3558 #9 0xffffffff81a86f54 in zfsdev_ioctl (dev=<optimized out>, zcmd=<optimized out>, arg=<optimized out>, flag=<optimized out>, td=<optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:6278 #10 0xffffffff80837469 in devfs_ioctl_f (fp=0xfffff8001ff5b8c0, com=3222821411, data=0xfffffe085e28b8e0, cred=<optimized out>, td=0xfffff80448797960) at /usr/src/sys/fs/devfs/devfs_vnops.c:786 #11 0xffffffff809aa085 in fo_ioctl (fp=<optimized out>, com=<optimized out>, data=<optimized out>, active_cred=<optimized out>, td=<optimized out>, fp=<optimized out>, com=<optimized out>, data=<optimized out>, active_cred=<optimized out>, td=<optimized out>) at /usr/src/sys/sys/file.h:321 #12 kern_ioctl (td=0xfffff80448797960, fd=<optimized out>, com=<unavailable>) at /usr/src/sys/kern/sys_generic.c:809 #13 0xffffffff809a9d80 in sys_ioctl (td=0xfffff80448797960, uap=0xfffffe085e28ba40) at /usr/src/sys/kern/sys_generic.c:718 #14 0xffffffff80d68aff in syscallenter (td=<optimized out>, sa=<optimized out>, td=<optimized out>, sa=<optimized out>) at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:141 #15 amd64_syscall (td=0xfffff80448797960, traced=0) at /usr/src/sys/amd64/amd64/trap.c:959 #16 <signal handler called> #17 0x0000000801a05f1a in ?? () Backtrace stopped: Cannot access memory at address 0x7fffffffc8c8