Test case vdev_zaps_004_pos

[behlendorf]

System information

Type	Version/Name
Distribution Name	all
Distribution Version	all
Linux Kernel	all
Architecture	all
ZFS Version	zfs-0.7.0-205-g1ce23dc
SPL Version	0.7

Describe the problem you're observing

Occasionally observed failure of vdev_zaps_004_pos during automated testing. This is caused by a problem with the test case which needs to be resolved before this test case can be re-enabed.

Describe how to reproduce the problem

Reproducible by the buildbot.

Include any warning/errors/backtraces from the system logs

http://build.zfsonlinux.org/builders/Ubuntu%2014.04%20i686%20%28TEST%29/builds/5046/steps/shell_8/logs/log

Test: /usr/share/zfs/zfs-tests/tests/functional/vdev_zaps/vdev_zaps_004_pos (run as root) [00:04] [FAIL]
17:22:09.36 ASSERTION: Per-vdev ZAPs are transferred properly on attach/detach
17:22:09.65 SUCCESS: zpool create -f testpool loop0
17:22:13.02 SUCCESS: zpool attach testpool loop0 loop1
17:22:13.65 

[loli10K]

I've added some debugging code to zdb on a local builder to investigate the issue.

The following backtrace shows zdb -PC testpool trying to read the pool configuration on "sda1" (txg=12 from spa_last_synced_txg()) but every label has a newer txg so it gets skipped (i added a new local label_txgs to track these values):

Core was generated by `zdb -PC testpool'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007fa107f1c067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56	../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  0x00007fa107f1c067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007fa107f1d448 in __GI_abort () at abort.c:89
#2  0x00007fa108c266b1 in libspl_assert (buf=0x7fa108d63a62 "config", file=0x7fa108d63349 "../../module/zfs/vdev_label.c", func=0x7fa108d63ea0 <__FUNCTION__.15375> "vdev_label_read_config", line=670)
    at ../../lib/libspl/include/assert.h:41
#3  0x00007fa108c27f0e in vdev_label_read_config (vd=0x14709e0, txg=12) at ../../module/zfs/vdev_label.c:670
#4  0x00007fa108c1e0df in vdev_validate (vd=0x14709e0, strict=B_TRUE) at ../../module/zfs/vdev.c:1500
#5  0x00007fa108c1e02e in vdev_validate (vd=0x146e1d0, strict=B_TRUE) at ../../module/zfs/vdev.c:1486
#6  0x00007fa108c1e02e in vdev_validate (vd=0x146b9c0, strict=B_TRUE) at ../../module/zfs/vdev.c:1486
#7  0x00007fa108bfb904 in spa_load_impl (ereport=0x7ffcebc93f48, mosconfig=B_TRUE, type=SPA_IMPORT_EXISTING, state=SPA_LOAD_OPEN, config=0x14d9fe0, pool_guid=16093360782817294222, spa=0x1466f50)
    at ../../module/zfs/spa.c:2614
#8  spa_load (spa=0x1466f50, state=SPA_LOAD_OPEN, type=SPA_IMPORT_EXISTING, mosconfig=B_TRUE) at ../../module/zfs/spa.c:2273
#9  0x00007fa108bfc631 in spa_load_impl (ereport=0x7ffcebc94128, mosconfig=B_FALSE, type=SPA_IMPORT_EXISTING, state=SPA_LOAD_OPEN, config=0x146b9f0, pool_guid=16093360782817294222, spa=0x1466f50)
    at ../../module/zfs/spa.c:2911
#10 spa_load (spa=0x1466f50, state=SPA_LOAD_OPEN, type=SPA_IMPORT_EXISTING, mosconfig=B_FALSE) at ../../module/zfs/spa.c:2273
#11 0x00007fa108bfdf22 in spa_load_best (spa=0x1466f50, state=SPA_LOAD_OPEN, mosconfig=0, max_request=18446744073709551615, rewind_flags=2) at ../../module/zfs/spa.c:3313
#12 0x00007fa108bfe3b5 in spa_open_common (pool=0x7ffcebcaec99 "testpool", spapp=0x7ffcebcaca58, tag=0x41ae53 <__func__.20351>, nvpolicy=0x1465fd0, config=0x7ffcebcaca38) at ../../module/zfs/spa.c:3441
#13 0x00007fa108bfe6bc in spa_open_rewind (name=0x7ffcebcaec99 "testpool", spapp=0x7ffcebcaca58, tag=0x41ae53 <__func__.20351>, policy=0x1465fd0, config=0x7ffcebcaca38) at ../../module/zfs/spa.c:3519
#14 0x00000000004152cc in main (argc=1, argv=0x7ffcebcacbe8) at zdb.c:4525
(gdb) frame 3
#3  0x00007fa108c27f0e in vdev_label_read_config (vd=0x14709e0, txg=12) at ../../module/zfs/vdev_label.c:670
warning: Source file is more recent than executable.
670		ASSERT(config);
(gdb) p vd->vdev_path
$1 = 0x14d5e80 "/dev/sda1"
(gdb) info locals
spa = 0x1466f50
config = 0x0
vp = 0x148d000
vp_abd = 0x14e5e10
zio = 0x14aaa70
best_txg = 0
error = 0
flags = 131968
configs = {0x14ab680, 0x14d7450, 0x14d71e0, 0x14d9fc0}
label_txgs = {13, 13, 13, 13}
errors = {0, 0, 0, 0}
__FUNCTION__ = "vdev_label_read_config"
(gdb) 

vdev_label_read_config() was going to return NULL: with a NULL config vdev_validate() sets the VDEV state to VDEV_STATE_CANT_OPEN:

(gdb) up
#4  0x00007fa108c1e0df in vdev_validate (vd=0x14709e0, strict=B_TRUE) at ../../module/zfs/vdev.c:1500
1500			if ((label = vdev_label_read_config(vd, txg)) == NULL) {
(gdb) list
1495			uint64_t aux_guid = 0;
1496			nvlist_t *nvl;
1497			uint64_t txg = spa_last_synced_txg(spa) != 0 ?
1498			    spa_last_synced_txg(spa) : -1ULL;
1499	
1500			if ((label = vdev_label_read_config(vd, txg)) == NULL) {
1501				vdev_set_state(vd, B_FALSE, VDEV_STATE_CANT_OPEN,
1502				    VDEV_AUX_BAD_LABEL);
1503				return (0);
(gdb) 

Ultimately we get a ENXIO from spa_load_impl() if rvd->vdev_state <= VDEV_STATE_CANT_OPEN, which explains the test case failing with "zdb: can't open 'testpool': No such device or address":

(gdb) up
#7  0x00007fa108bfb904 in spa_load_impl (ereport=0x7ffcebc93f48, mosconfig=B_TRUE, type=SPA_IMPORT_EXISTING, state=SPA_LOAD_OPEN, config=0x14d9fe0, pool_guid=16093360782817294222, spa=0x1466f50)
    at ../../module/zfs/spa.c:2614
2614			error = vdev_validate(rvd, mosconfig);
(gdb) list
2609		 * existing pool, the labels haven't yet been updated so we skip
2610		 * validation for now.
2611		 */
2612		if (type != SPA_IMPORT_ASSEMBLE) {
2613			spa_config_enter(spa, SCL_ALL, FTAG, RW_WRITER);
2614			error = vdev_validate(rvd, mosconfig);
2615			spa_config_exit(spa, SCL_ALL, FTAG);
2616	
2617			if (error != 0)
2618				return (error);
(gdb) 
2619	
2620			if (rvd->vdev_state <= VDEV_STATE_CANT_OPEN) {
2621				return (SET_ERROR(ENXIO));
2622			}
2623		}
2624	
2625		/*
2626		 * Find the best uberblock.
2627		 */
(gdb) 

Having a txg number on every label higher than spa_last_synced_txg() seems like it could be explained by some sort of race-condition; i'm still investigating this. Also, reverting to the legacy scrub code (echo 1 > /sys/module/zfs/parameters/zfs_scan_legacy) seems to fix the issue.

[stale]

This issue has been automatically marked as "stale" because it has not had any activity for a while. It will be closed in 90 days if no further activity occurs. Thank you for your contributions.