I've had two ZFS-related kernel panics over the last few days. Both have happened since I upgraded to 9.1-RELEASE-4 on the 18th. PR 154447 has similar backtraces but was on 8.2, I can't find any other references to a similar problem. It's a mixed UFS/ZFS system, root is on UFS with a single 4-disk RAIDZ1 pool used for backups, a media library, poudriere and a few other jails. I replaced one of the disks in the pool earlier this week which had been failing for a while and have been tuning the ZFS settings based on this guide: http://icesquare.com/wordpress/how-to-improve-zfs-performance/ after I upgraded to 4Gb RAM. Jun 25 08:12:57 masada kernel: panic: solaris assert: dsl_prop_unregister(ds, "atime", atime_changed_cb, zfsvfs) == 0, file: /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c, line: 1199 Jun 25 08:12:57 masada kernel: cpuid = 0 Jun 25 08:12:57 masada kernel: KDB: stack backtrace: Jun 25 08:12:57 masada kernel: #0 0xffffffff80926c96 at kdb_backtrace+0x66 Jun 25 08:12:57 masada kernel: #1 0xffffffff808f0cae at panic+0x1ce Jun 25 08:12:57 masada kernel: #2 0xffffffff816b5647 at zfs_unregister_callbacks+0x1b7 Jun 25 08:12:57 masada kernel: #3 0xffffffff816b58c5 at zfsvfs_teardown+0x175 Jun 25 08:12:57 masada kernel: #4 0xffffffff816b5a2b at zfs_suspend_fs+0x1b Jun 25 08:12:57 masada kernel: #5 0xffffffff816aa229 at zfs_ioc_rollback+0xf9 Jun 25 08:12:57 masada kernel: #6 0xffffffff816abd46 at zfsdev_ioctl+0xe6 Jun 25 08:12:57 masada kernel: #7 0xffffffff807e077b at devfs_ioctl_f+0x7b Jun 25 08:12:57 masada kernel: #8 0xffffffff80938715 at kern_ioctl+0x115 Jun 25 08:12:57 masada kernel: #9 0xffffffff8093894d at sys_ioctl+0xfd Jun 25 08:12:57 masada kernel: #10 0xffffffff80be71d6 at amd64_syscall+0x546 Jun 28 04:08:02 masada kernel: panic: solaris assert: dsl_prop_unregister(ds, "snapdir", snapdir_changed_cb, zfsvfs) == 0, file: /usr/src/sys/modules/zfs/../.. /cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c, line: 1217 Jun 28 04:08:02 masada kernel: cpuid = 1 Jun 28 04:08:02 masada kernel: KDB: stack backtrace: Jun 28 04:08:02 masada kernel: #0 0xffffffff80926c96 at kdb_backtrace+0x66 Jun 28 04:08:02 masada kernel: #1 0xffffffff808f0cae at panic+0x1ce Jun 28 04:08:02 masada kernel: #2 0xffffffff816b570d at zfs_unregister_callbacks+0x27d Jun 28 04:08:02 masada kernel: #3 0xffffffff816b58c5 at zfsvfs_teardown+0x175 Jun 28 04:08:02 masada kernel: #4 0xffffffff816b5a2b at zfs_suspend_fs+0x1b Jun 28 04:08:02 masada kernel: #5 0xffffffff816aa229 at zfs_ioc_rollback+0xf9 Jun 28 04:08:02 masada kernel: #6 0xffffffff816abd46 at zfsdev_ioctl+0xe6 Jun 28 04:08:02 masada kernel: #7 0xffffffff807e077b at devfs_ioctl_f+0x7b Jun 28 04:08:02 masada kernel: #8 0xffffffff80938715 at kern_ioctl+0x115 Jun 28 04:08:02 masada kernel: #9 0xffffffff8093894d at sys_ioctl+0xfd Jun 28 04:08:02 masada kernel: #10 0xffffffff80be71d6 at amd64_syscall+0x546 How-To-Repeat: I think it's more likely to happen under heavy IO load. This machine has rsnaphot backups scheduled to run every 4 hours, both of the crashes have occurred shortly after a backup began. It was also building packages with poudriere at the same time in both instances.
Responsible Changed From-To: freebsd-bugs->freebsd-zfs-devel Over to maintainer(s).
Do you have mountd running ? I have a similiar configuration and the same problem with FreeBSD dsssrvt4.incore 8.4-STABLE FreeBSD 8.4-STABLE #0 r253040:amd64. and found the panic is caused by mountd. This daemon starts working on every successfull mount (sends signal 1 to mountd) and tries to delete all existing exports for all local file systems using the flag MNT_DELEXPORT. mountd calls nmount() and sometimes I see messages like mountd[56874]: can't delete exports for /home/poudriere/data/build/j8sp32-PT2/02/new_packages: Invalid argument and once a week I have a panic: panic: solaris assert: dsl_prop_unregister(ds, "aclinherit", acl_inherit_changed_cb, zfsvfs) == 0, file: /usr/src/sys/module s/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c, line: 1279 cpuid = 1 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2a kdb_backtrace() at kdb_backtrace+0x37 panic() at panic+0x1ce assfail() at assfail+0x1a zfs_unregister_callbacks() at zfs_unregister_callbacks+0x1c8 zfsvfs_teardown() at zfsvfs_teardown+0x179 zfs_suspend_fs() at zfs_suspend_fs+0x1b zfs_ioc_rollback() at zfs_ioc_rollback+0x24 zfsdev_ioctl() at zfsdev_ioctl+0x57f devfs_ioctl_f() at devfs_ioctl_f+0x7b kern_ioctl() at kern_ioctl+0x102 ioctl() at ioctl+0xfd amd64_syscall() at amd64_syscall+0x1f4(kgdb) where(kgdb) where Xfast_syscall() at Xfast_syscall+0xfc --- syscall (54, FreeBSD ELF64, ioctl), rip = 0x180fd0c1c, rsp = 0x7fffffffce48, rbp = 0x7fffffffcf50 --- KDB: enter: panic This process panics on dsl_prop_unregister of "aclinherit" during a rollback: 39024 38985 81834 0 R+ CPU 0 initial thread (kgdb) where #9 0xffffffff804328fb in kdb_enter (why=0xffffffff8069543a "panic", msg=0xa <Address 0xa out of bounds>) at cpufunc.h:63 #10 0xffffffff803ff367 in panic (fmt=<value optimized out>) at /usr/src/sys/kern/kern_shutdown.c:616 #11 0xffffffff80d5712a in assfail (a=<value optimized out>, f=<value optimized out>, l=<value optimized out>) at /usr/src/sys/modules/opensolaris/../../cddl/compat/opensolaris/kern/opensolaris_cmn_err.c:81 #12 0xffffffff80cbd0b8 in zfs_unregister_callbacks (zfsvfs=0xffffff01f5664000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1278 #13 0xffffffff80cbd319 in zfsvfs_teardown (zfsvfs=0xffffff01f5664000, unmounting=0) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1919 #14 0xffffffff80cbd42b in zfs_suspend_fs (zfsvfs=0xffffff01f5664000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:2225 #15 0xffffffff80cb0364 in zfs_ioc_rollback (zc=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:3565 #16 0xffffffff80cb4abf in zfsdev_ioctl (dev=<value optimized out>, zcmd=<value optimized out>, arg=0xffffff00720a81a0 "\003", flag=3,td=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:5936 #17 0xffffffff8037703b in devfs_ioctl_f (fp=0xffffff0008cce0f0, com=3222821401, data=<value optimized out>, cred=<value optimized out>, td=0xffffff02439d5000) at /usr/src/sys/fs/devfs/devfs_vnops.c:695 #18 0xffffffff80444902 in kern_ioctl (td=<value optimized out>, fd=<value optimized out>, com=3222821401, data=0xffffff00720a81a0 "\003") at file.h:277 #19 0xffffffff80444b3d in ioctl (td=0xffffff02439d5000, uap=0xffffff84859e1bb0) at /usr/src/sys/kern/sys_generic.c:679 #20 0xffffffff805db824 in amd64_syscall (td=0xffffff02439d5000, traced=0) at subr_syscall.c:114 #21 0xffffffff805c2e9c in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:387 This process has just done dsl_prop_register "aclinherit" and sleeps: 56874 1 56874 0 Ss zio->io_ 0xffffff02f41a8e48 mountd (kgdb) thread 304 [Switching to thread 304 (Thread 100357)]#0 sched_switch (td=0xffffff0013717000, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1932 1932 cpuid = PCPU_GET(cpuid); (kgdb) where #0 sched_switch (td=0xffffff0013717000, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1932 #1 0xffffffff80407d16 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:466 #2 0xffffffff8043e5c2 in sleepq_wait (wchan=0xffffff02c000ee48, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:613 #3 0xffffffff803b9971 in _cv_wait (cvp=0xffffff02c000ee48, lock=0xffffff02c000ee28) at /usr/src/sys/kern/kern_condvar.c:139 #4 0xffffffff80c9e9f1 in zio_wait (zio=0xffffff02c000eb10) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1332 #5 0xffffffff80c35588 in dbuf_read (db=0xffffff01f7dbca80, zio=0x0, flags=10) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c:639 #6 0xffffffff80c3bcc0 in dmu_buf_hold (os=<value optimized out>, object=<value optimized out>, offset=<value optimized out>, tag=0x0, dbp=0xffffff8484d1b150, flags=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/dmu.c:151 #7 0xffffffff80c8f4f8 in zap_lockdir (os=0xffffff0013274000, obj=2558, tx=0x0, lti=RW_READER, fatreader=1, adding=0,zapp=0xffffff8484d1b1b0) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:467 #8 0xffffffff80c90b15 in zap_lookup_norm (os=<value optimized out>, zapobj=<value optimized out>, name=0xffffffff80d31204 "aclinherit", integer_size=8, num_integers=1, buf=0xffffff8484d1b340, mt=MT_EXACT, realname=0x0, rn_len=0, ncp=0x0) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:788 #9 0xffffffff80c90cbe in zap_lookup (os=<value optimized out>, zapobj=<value optimized out>, name=<value optimized out>, integer_size=<value optimized out>, num_integers=<value optimized out>, buf=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:773 9 0xffffffff80c90cbe in zap_lookup (os=<value optimized out>, zapobj=<value optimized out>, name=<value optimized out>, integer_size=<value optimized out>, num_integers=<value optimized out>, buf=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:773 #10 0xffffffff80c5e6d0 in dsl_prop_get_dd (dd=0xffffff03d070c800, propname=0xffffffff80d31204 "aclinherit", intsz=8, numints=1, buf=0xffffff8484d1b340, setpoint=0x0, snapshot=0) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/dsl_prop.c:107 #11 0xffffffff80c5e90b in dsl_prop_get_ds (ds=0xffffff0126912c00, propname=0xffffffff80d31204 "aclinherit", intsz=8, numints=1, buf=0xffffff8484d1b340, setpoint=0x0) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/dsl_prop.c:216 #12 0xffffffff80c5f496 in dsl_prop_register (ds=0xffffff0126912c00, propname=0xffffffff80d31204 "aclinherit", callback=0xffffffff80cbca40 <acl_inherit_changed_cb>, cbarg=0xffffff01f5664000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/dsl_prop.c:239 #13 0xffffffff80cbdd6b in zfs_register_callbacks (vfsp=<value optimized out>) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:518 #14 0xffffffff80cc0048 in zfs_mount (vfsp=0xffffff03e49398d0) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1706 #15 0xffffffff8048d0a7 in vfs_donmount (td=<value optimized out>, fsflags=268505104, fsoptions=0xffffff03b8026c00) at /usr/src/sys/kern/vfs_mount.c:1011 #16 0xffffffff8048dc53 in nmount (td=0xffffff0013717000, uap=0xffffff8484d1bbb0) at /usr/src/sys/kern/vfs_mount.c:447 #17 0xffffffff805db824 in amd64_syscall (td=0xffffff0013717000, traced=0) at subr_syscall.c:114 #18 0xffffffff805c2e9c in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:387 (kgdb) f 15 #15 0xffffffff8048d0a7 in vfs_donmount (td=<value optimized out>, fsflags=268505104, fsoptions=0xffffff03b8026c00) at /usr/src/sys/kern/vfs_mount.c:1011 1011 error = VFS_MOUNT(mp); (kgdb) info local optlist = (struct vfsoptlist *) 0xffffff008edc20b0 opt = <value optimized out> tmp_opt = <value optimized out> fstype = 0xffffff008eda9050 "zfs" fspath = 0xffffff03011760c0 "/home/poudriere/data/build/j8sp32-PT2/01" errmsg = 0xffffff03abfae800 "" error = <value optimized out> fstypelen = 4 fspathlen = 41 errmsg_len = 255 errmsg_pos = 5 has_rw = 0 has_noro = 0 I can give more information from ddb output or kernel dump. -- Andreas Longwitz
On 2013-07-25 23:52:54(+0200), Andreas Longwitz wrote: > Do you have mountd running ? Yes. > I have a similiar configuration and the same problem with > > FreeBSD dsssrvt4.incore 8.4-STABLE FreeBSD 8.4-STABLE #0 r253040:amd64. > > and found the panic is caused by mountd. This daemon starts working on > every successfull mount (sends signal 1 to mountd) and tries to delete > all existing exports for all local file systems using the flag > MNT_DELEXPORT. mountd calls nmount() and sometimes I see messages like > > mountd[56874]: can't delete exports for > /home/poudriere/data/build/j8sp32-PT2/02/new_packages: Invalid argument > > and once a week I have a panic: I think I also had errors from mountd around the time of the panics but I haven't had one for a while (mainly due to reducing the frequency of poudriere runs) so I can't be sure. I will try disabling mountd and see if that eliminates the problem, all my NFS clients are using NFSv4 so I don't need it running. James -- }-<James TD Smith>-<email/ahktenzero@mohorovi.cc>-{
In the meantime I did some more analysis of the problem and can explain why the panic happens. Two threads are involved in the problem, one runs the zfs command and wants to do a rollback using an ioctl() on /dev/zfs, the other runs mountd and tries to do an "unmount exports" with "export.ex_flags = MNT_DELEXPORT". Both threads are working on the same dataset ds=0xffffff0126912c00. The rollback thread wants to unregister his aclinherit property and panics, because this property does not exist in the list of properties anymore: (kgdb) f 12 #12 0xffffffff80cbd0b8 in zfs_unregister_callbacks (zfsvfs=0xffffff01f5664000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1278 1278 VERIFY(dsl_prop_unregister(ds, "aclinherit", (kgdb) l 1273 zfsvfs) == 0); 1274 1275 VERIFY(dsl_prop_unregister(ds, "aclmode", acl_mode_changed_cb, 1276 zfsvfs) == 0); 1277 1278 VERIFY(dsl_prop_unregister(ds, "aclinherit", 1279 acl_inherit_changed_cb, zfsvfs) == 0); 1280 1281 VERIFY(dsl_prop_unregister(ds, "vscan", 1282 vscan_changed_cb, zfsvfs) == 0); The mountd thread wants to register some properties, but he first unregisters everything (see comment in the source): (kgdb) f 14 #14 0xffffffff80cc0048 in zfs_mount (vfsp=0xffffff03e49398d0) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1706 1706 error = zfs_register_callbacks(vfsp); (kgdb) list 1700 * When doing a remount, we simply refresh our temporary properties 1701 * according to those options set in the current VFS options. 1702 */ 1703 if (vfsp->vfs_flag & MS_REMOUNT) { 1704 /* refresh mount options */ 1705 zfs_unregister_callbacks(vfsp->vfs_data); 1706 error = zfs_register_callbacks(vfsp); 1707 goto out; 1708 } 1709 There is a little time gap between line 1705 and 1706 where the property aclinherit is not registered. If another thread tries to unregister this property during this gap he will panic. I don't know how to fix this proper. Simple to remove the VERIFY on dsl_prop_unregister() is easy, but I hope that one of the ZFS gurus will have a look at this and we will get a better solution. -- Andreas Longwitz
Please see the following suggestion: http://article.gmane.org/gmane.os.illumos.zfs/2833 Will you be able to work on a patch that implements the idea? -- Andriy Gapon
Andriy Gapon wrote > Please see the following suggestion: > http://article.gmane.org/gmane.os.illumos.zfs/2833 > Will you be able to work on a patch that implements the idea? Sorry, but that is out of my scope. Andreas Longwitz
Created attachment 157329 [details] console screenshot of panic
Created attachment 157799 [details] proposed patch for testing commit 7fb40408aea1be27984cc25dd80e707c9dbc2f05 Author: Andriy Gapon <avg@icyb.net.ua> If anyone is still running into the issue, could you please test the attached patch? zfs_mount(MS_REMOUNT): protect zfs_(un)register_callbacks calls We now take z_teardown_lock as a writer to ensure that there is no I/O while the filesystem state is in a flux. Also, zfs_suspend_fs() -> zfsvfs_teardown() call zfs_unregister_callbacks() and zfs_resume_fs() -> zfsvfs_setup() call zfs_unregister_callbacks(). Previously there was no synchronization between those calls and the calls in the re-mounting case. That could lead to concurrent execution and a crash. PR: 180060 Suggested by: mahrens
See review D2865
A commit references this bug: Author: avg Date: Thu Jul 2 08:32:03 UTC 2015 New revision: 285021 URL: https://svnweb.freebsd.org/changeset/base/285021 Log: zfs_mount(MS_REMOUNT): protect zfs_(un)register_callbacks calls We now take z_teardown_lock as a writer to ensure that there is no I/O while the filesystem state is in a flux. Also, zfs_suspend_fs() -> zfsvfs_teardown() call zfs_unregister_callbacks() and zfs_resume_fs() -> zfsvfs_setup() call zfs_unregister_callbacks(). Previously there was no synchronization between those calls and the calls in the re-mounting case. That could lead to concurrent execution and a crash. PR: 180060 Differential Revision: https://reviews.freebsd.org/D2865 Suggested by: mahrens Reviewed by: delphij, pho, mahrens, will MFC after: 13 days Sponsored by: ClusterHQ Changes: head/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c
Should be fixed now.