From owner-freebsd-fs@FreeBSD.ORG Thu Mar 20 21:20:02 2014 Return-Path: Delivered-To: freebsd-fs@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 7C2104B2 for ; Thu, 20 Mar 2014 21:20:02 +0000 (UTC) Received: from dss.incore.de (dss.incore.de [195.145.1.138]) by mx1.freebsd.org (Postfix) with ESMTP id D6C565E4 for ; Thu, 20 Mar 2014 21:20:01 +0000 (UTC) Received: from inetmail.dmz (inetmail_new [10.3.0.4]) by dss.incore.de (Postfix) with ESMTP id 9D8D05C025 for ; Thu, 20 Mar 2014 22:13:52 +0100 (CET) X-Virus-Scanned: amavisd-new at incore.de Received: from dss.incore.de ([10.3.0.3]) by inetmail.dmz (inetmail.dmz [10.3.0.4]) (amavisd-new, port 10024) with LMTP id 8ktsBVknpL81 for ; Thu, 20 Mar 2014 22:13:50 +0100 (CET) Received: from mail.incore (fwintern.dmz [10.0.0.253]) by dss.incore.de (Postfix) with ESMTP id 28D825C01E for ; Thu, 20 Mar 2014 22:13:50 +0100 (CET) Received: from bsdmhs.longwitz (unknown [192.168.99.6]) by mail.incore (Postfix) with ESMTP id 3EB4750865 for ; Thu, 20 Mar 2014 22:13:49 +0100 (CET) Message-ID: <532B5A0C.1010008@incore.de> Date: Thu, 20 Mar 2014 22:13:48 +0100 From: Andreas Longwitz User-Agent: Thunderbird 2.0.0.19 (X11/20090113) MIME-Version: 1.0 To: freebsd-fs@freebsd.org Subject: Kernel crash trying to import a ZFS pool with log device Content-Type: text/plain; charset=ISO-8859-15 Content-Transfer-Encoding: 8bit X-BeenThere: freebsd-fs@freebsd.org X-Mailman-Version: 2.1.17 Precedence: list List-Id: Filesystems List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 20 Mar 2014 21:20:02 -0000 On a maschine running FreeBSD 8.4-STABLE #0 r256119 I have loader.conf: vfs.zfs.vdev.bio_delete_disable=1 -> glabel status Name Status Components label/C325BL31 N/A da2 label/C330CJHW N/A da3 -> gmirror status Name Status Components mirror/gmsv09 COMPLETE da0 (ACTIVE) da1 (ACTIVE) mirror/gm0 COMPLETE da4 (ACTIVE) da5 (ACTIVE) -> zpool status pool: mpool state: ONLINE scan: scrub repaired 0 in 0h0m with 0 errors on Sat Mar 15 06:15:36 2014 config: NAME STATE READ WRITE CKSUM mpool ONLINE 0 0 0 mirror-0 ONLINE 0 0 0 label/C325BL31 ONLINE 0 0 0 label/C330CJHW ONLINE 0 0 0 errors: No known data errors I can run "zpool export mpool" and "zpool import [mpool]" without any problems. After adding a log device from a free partition of a gmirrored disk with -> zpool add mpool log /dev/mirror/gm0p3 the pool runs fine and I have -> zpool status pool: mpool state: ONLINE scan: scrub repaired 0 in 0h0m with 0 errors on Sat Mar 15 06:15:36 2014 config: NAME STATE READ WRITE CKSUM mpool ONLINE 0 0 0 mirror-0 ONLINE 0 0 0 label/C325BL31 ONLINE 0 0 0 label/C330CJHW ONLINE 0 0 0 logs mirror/gm0p3 ONLINE 0 0 0 errors: No known data errors But if I now run "zpool export" and "zpool import" the kernel crashes: ... vdev_geom_open_by_path:554[1]: Found provider by name /dev/label/C325BL31. vdev_geom_attach:102[1]: Attaching to label/C325BL31. g_access(0xffffff0096b23a00(label/C325BL31), 1, 0, 1) open delta:[r1w0e1] old:[r0w0e0] provider:[r0w0e0] 0xffffff0002c0d400(label/C325BL31) g_access(0xffffff0002ba7300(da2), 1, 0, 2) open delta:[r1w0e2] old:[r0w0e0] provider:[r0w0e0] 0xffffff0002a23800(da2) g_disk_access(da2, 1, 0, 2) vdev_geom_attach:123[1]: Created geom and consumer for label/C325BL31. vdev_geom_read_config:248[1]: Reading config from label/C325BL31... vdev_geom_open_by_path:569[1]: guid match for provider /dev/label/C325BL31. vdev_geom_open_by_path:554[1]: Found provider by name /dev/label/C330CJHW. vdev_geom_attach:102[1]: Attaching to label/C330CJHW. g_access(0xffffff00969a5280(label/C330CJHW), 1, 0, 1) open delta:[r1w0e1] old:[r0w0e0] provider:[r0w0e0] 0xffffff0002c02100(label/C330CJHW) g_access(0xffffff0002b96280(da3), 1, 0, 2) open delta:[r1w0e2] old:[r0w0e0] provider:[r0w0e0] 0xffffff0002a23b00(da3) g_disk_access(da3, 1, 0, 2) vdev_geom_attach:143[1]: Created consumer for label/C330CJHW. vdev_geom_read_config:248[1]: Reading config from label/C330CJHW... vdev_geom_open_by_path:569[1]: guid match for provider /dev/label/C330CJHW. vdev_geom_open_by_path:554[1]: Found provider by name /dev/mirror/gm0p3. vdev_geom_attach:102[1]: Attaching to mirror/gm0p3. g_access(0xffffff0096b24180(mirror/gm0p3), 1, 0, 1) open delta:[r1w0e1] old:[r0w0e0] provider:[r0w0e0] 0xffffff00969c7e00(mirror/gm0p3) g_part_access(mirror/gm0p3,1,0,1) g_access(0xffffff0096c0f800(mirror/gm0), 1, 0, 1) open delta:[r1w0e1] old:[r8w8e16] provider:[r8w8e16] 0xffffff00969c7d00(mirror/gm0) GEOM_MIRROR[2]: Access request for mirror/gm0: r1w0e1. vdev_geom_attach:143[1]: Created consumer for mirror/gm0p3. vdev_geom_read_config:248[1]: Reading config from mirror/gm0p3... vdev_geom_open_by_path:569[1]: guid match for provider /dev/mirror/gm0p3. g_post_event_x(0xffffffff80b16830, 0xffffff0096b24180, 2, 0) vdev_geom_detach:163[1]: Closing access to mirror/gm0p3. g_access(0xffffff0096b24180(mirror/gm0p3), -1, 0, -1) open delta:[r-1w0e-1] old:[r1w0e1] provider:[r1w0e1] 0xffffff00969c7e00(mirror/gm0p3) g_part_access(mirror/gm0p3,-1,0,-1) g_access(0xffffff0096c0f800(mirror/gm0), -1, 0, -1) open delta:[r-1w0e-1] old:[r9w8e17] provider:[r9w8e17] 0xffffff00969c7d00(mirror/gm0) GEOM_MIRROR[2]: Access request for mirror/gm0: r-1w0e-1. vdev_geom_open_by_path:554[1]: Found provider by name /dev/mirror/gm0p3. vdev_geom_attach:102[1]: Attaching to mirror/gm0p3. vdev_geom_attach:128[1]: Found consumer for mirror/gm0p3. g_access(0xffffff0096b24180(mirror/gm0p3), 1, 0, 1) open delta:[r1w0e1] old:[r1w0e1] provider:[r1w0e1] 0xffffff00969c7e00(mirror/gm0p3) g_part_access(mirror/gm0p3,1,0,1) g_access(0xffffff0096c0f800(mirror/gm0), 1, 0, 1) Open delta:[r1w0e1] old:[r9w8e17] provider:[r9w8e17] 0xffffff00969c7d00(mirror/gm0) GEOM_MIRROR[2]: Access request for mirror/gm0: r1w0e1. vdev_geom_detach:167[1]: Destroyed consumer to mirror/gm0p3. g_detach(0xffffff0096b24180) g_destroy_consumer(0xffffff0096b24180) vdev_geom_attach:147[1]: Used existing consumer for mirror/gm0p3. vdev_geom_read_config:248[1]: Fatal trap 12: page fault while in kernel mode cpuid = 1; apic id = 01 fault virtual address = 0x0 fault code = supervisor read data, page not present instruction pointer = 0x20:0xffffffff80b16f01 stack pointer = 0x28:0xffffff82452325b0 frame pointer = 0x28:0xffffff8245232650 code segment = base 0x0, limit 0xfffff, type 0x1b = DPL 0, pres 1, long 1, def32 0, gran 1 processor eflags = interrupt enabled, resume, IOPL = 0 current process = 15494 (initial thread) [thread pid 15494 tid 100151 ] Stopped at vdev_geom_read_config+0x71: movq (%rdx),%rsi (kgdb) where ... #9 0xffffffff805dce1b in trap (frame=0xffffff8245232500) at /usr/src/sys/amd64/amd64/trap.c:457 #10 0xffffffff805c3024 in calltrap () at /usr/src/sys/amd64/amd64/exception.S:228 #11 0xffffffff80b16f01 in vdev_geom_read_config (cp=0xffffff0096b24180, config=0xffffff8245232670) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c:248 #12 0xffffffff80b17194 in vdev_geom_read_guid (cp=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c:454 #13 0xffffffff80b172f0 in vdev_geom_open_by_path (vd=0xffffff0002b2f000, check_guid=1) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c:559 #14 0xffffffff80b17528 in vdev_geom_open (vd=0xffffff0002b2f000, psize=0xffffff8245232760, max_psize=0xffffff8245232758, ashift=0xffffff8245232750) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c:608 #15 0xffffffff80aca87a in vdev_open (vd=0xffffff0002b2f000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev.c:1153 #16 0xffffffff80acac5e in vdev_reopen (vd=0xffffff0002b2f000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev.c:1514 #17 0xffffffff80ab84e0 in spa_load (spa=0xffffff0002b85000, state=SPA_LOAD_TRYIMPORT, type=SPA_IMPORT_EXISTING, mosconfig=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:1654 #18 0xffffffff80abaa40 in spa_tryimport (tryconfig=0xffffff00024b2260) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:4184 #19 0xffffffff80afb486 in zfs_ioc_pool_tryimport (zc=0xffffff8001f1d000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:1630 #20 0xffffffff80afea7f in zfsdev_ioctl (dev=, zcmd=, arg=0xffffff00966154c0 "\003", flag=3, td=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:5945 #21 0xffffffff8037729b in devfs_ioctl_f (fp=0xffffff0002c98960, com=3222821382, data=, cred=, td=0xffffff0096017000) at /usr/src/sys/fs/devfs/devfs_vnops.c:700 #22 0xffffffff80444b22 in kern_ioctl (td=, fd=, com=3222821382, data=0xffffff00966154c0 "\003") at file.h:277 #23 0xffffffff80444d5d in ioctl (td=0xffffff0096017000, uap=0xffffff8245232bb0) at /usr/src/sys/kern/sys_generic.c:679 #24 0xffffffff805dbca4 in amd64_syscall (td=0xffffff0096017000, traced=0) at subr_syscall.c:114 #25 0xffffffff805c331c in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:387 #26 0x0000000180fcec2c in ?? () (kgdb) f 11 #11 0xffffffff80b16f01 in vdev_geom_read_config (cp=0xffffff0096b24180, config=0xffffff8245232670) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c:248 248 ZFS_LOG(1, "Reading config from %s...", pp->name); (kgdb) list 243 int error, l, len; 244 245 g_topology_assert_not(); 246 247 pp = cp->provider; 248 ZFS_LOG(1, "Reading config from %s...", pp->name); 249 250 psize = pp->mediasize; 251 psize = P2ALIGN(psize, (uint64_t)sizeof(vdev_label_t)); 252 (kgdb) p *cp $1 = {geom = 0xffffff0002c0dd00, consumer = {le_next = 0xffffff00969a5280, le_prev = 0xffffff0002c0dd20}, provider = 0x0, consumers = {le_next = 0xffffff009607bb00, le_prev = 0xffffff00969c7e20}, acr = 1, acw = 0, ace = 1, spoiled = 0, stat = 0xffffff0002bed5a0, nstart = 17, nend = 17, private = 0x0, index = 0} (kgdb) p *cp->provider Cannot access memory at address 0x0 (kgdb) f 12 #12 0xffffffff80b17194 in vdev_geom_read_guid (cp=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c:454 454 if (vdev_geom_read_config(cp, &config) == 0) { (kgdb) p *cp $2 = {geom = 0xffffff0002c0dd00, consumer = {le_next = 0xffffff00969a5280, le_prev = 0xffffff0002c0dd20}, provider = 0x0, consumers = {le_next = 0xffffff009607bb00, le_prev = 0xffffff00969c7e20}, acr = 1, acw = 0, ace = 1, spoiled = 0, stat = 0xffffff0002bed5a0, nstart = 17, nend = 17, private = 0x0, index = 0} (kgdb) info local config = (nvlist_t *) 0xffffff0002b85000 guid = 0 (kgdb) list 449 uint64_t guid; 450 451 g_topology_assert_not(); 452 453 guid = 0; 454 if (vdev_geom_read_config(cp, &config) == 0) { 455 guid = nvlist_get_guid(config); 456 nvlist_free(config); 457 } 458 return (guid); (kgdb) f 13 #13 0xffffffff80b172f0 in vdev_geom_open_by_path (vd=0xffffff0002b2f000, check_guid=1) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c:559 559 guid = vdev_geom_read_guid(cp); (kgdb) list 554 ZFS_LOG(1, "Found provider by name %s.", vd->vdev_path); 555 cp = vdev_geom_attach(pp); 556 if (cp != NULL && check_guid && ISP2(pp->sectorsize) && 557 pp->sectorsize <= VDEV_PAD_SIZE) { 558 g_topology_unlock(); 559 guid = vdev_geom_read_guid(cp); 560 g_topology_lock(); 561 if (guid != vd->vdev_guid) { 562 vdev_geom_detach(cp, 0); 563 cp = NULL; (kgdb) info local pp = (struct g_provider *) 0xffffff00969c7e00 cp = (struct g_consumer *) 0xffffff0096b24180 guid = __func__ = "ÿÿ\000\000H\213uÀ\211Ø\211\235üþÿÿ\203À\001\205ÀH\213" (kgdb) p *cp $3 = {geom = 0xffffff0002c0dd00, consumer = {le_next = 0xffffff00969a5280, le_prev = 0xffffff0002c0dd20}, provider = 0x0, consumers = {le_next = 0xffffff009607bb00, le_prev = 0xffffff00969c7e20}, acr = 1, acw = 0, ace = 1, spoiled = 0, stat = 0xffffff0002bed5a0, nstart = 17, nend = 17, private = 0x0, index = 0} (kgdb) p *pp $4 = {name = 0xffffff00969c7e88 "mirror/gm0p3", provider = {le_next = 0xffffff009698a100, le_prev = 0xffffff0002c03208}, geom = 0xffffff0002c68000, consumers = {lh_first = 0xffffff009607bb00}, acr = 1, acw = 0, ace = 1, error = 0, orphan = { tqe_next = 0x0, tqe_prev = 0x0}, mediasize = 8589934592, sectorsize = 512, stripesize = 0, stripeoffset = 226575360, stat = 0xffffff0002be7120, nstart = 157, nend = 157, flags = 0, private = 0xffffff00969c7c00, index = 2} (kgdb) quit The technical reason for the crash is that in "f 11" we have pp = cp->provider = 0. I can give more information from the kernel dump, also I can easy repeat the crash. -- Andreas Longwitz