search

openzfs / zfs

OpenZFS on Linux and FreeBSD
https://openzfs.github.io/openzfs-docs
Other
10.63k stars 1.75k forks source link

test case: removal_with_export #7450

Closed bunder2015 closed 3 years ago

bunder2015 commented 6 years ago

System information

Type Version/Name
Distribution Name gentoo
Distribution Version n/a
Linux Kernel 4.9.75
Architecture amd64
ZFS Version d68ac65e
SPL Version 9125f8f5

Describe the problem you're observing

Test failed during routine testing, this may just be a one-off, posting for verification. I don't actually know what killed off the test.

Describe how to reproduce the problem

Run tests

Include any warning/errors/backtraces from the system logs

NOTE: begin default_setup_noexit
SUCCESS: zpool create -f testpool loop0 loop1 loop2
SUCCESS: zfs create testpool/testfs
SUCCESS: zfs set mountpoint=/var/tmp/testdir testpool/testfs
SUCCESS: mkfile 1g /var/tmp/testdir/testfile0
NOTE: Starting writer for /var/tmp/testdir/testfile0
SUCCESS: zpool remove testpool loop0
ERROR: zpool export testpool exited 1
/home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export.ksh[48]: test_removal_with_operation[126]: log_must[67]: log_pos[253]: wait_for_removal[39]: log_must[67]: log_pos[253]: _test_removal_with_operation_cb[78]: callback[31]: test_removal_with_operation_kill[156]: wait: 15869: Terminated
umount: /var/tmp/testdir: target is busy. cannot unmount '/var/tmp/testdir': umount failed
NOTE: Performing test-fail callback (/home/testuser/zfs/tests/zfs-tests/callbacks/zfs_dbgmsg.ksh)
=================================================================
 Tailing last 200 lines of zfs_dbgmsg log
=================================================================
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 85
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 86
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 87
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 88
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 89
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 90
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 91
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 92
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 93
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 94
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 95
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 96
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 97
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 98
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 99
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 100
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 102
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 103
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 104
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 105
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 106
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 107
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 108
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 109
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 110
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 111
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 112
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 113
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 114
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 115
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 116
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 117
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 118
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 119
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 120
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 121
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 122
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 123
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 124
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 125
1523923646   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 126
1523923646   vdev_indirect_mapping.c:495:vdev_indirect_mapping_add_entries(): txg 21: wrote 13 entries to indirect mapping obj 141; max offset=0x80400
1523923646   spa_history.c:309:spa_history_log_sync(): command: zpool remove testpool loop0
1523923646   vdev_removal.c:1007:vdev_remove_complete(): finishing device removal for vdev 0 in txg 27
1523923646   spa_history.c:322:spa_history_log_sync(): txg 27 vdev remove completed testpool vdev 0
1523923647   spa_history.c:309:spa_history_log_sync(): command: zpool destroy -f testpool
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 create pool version 5000; software version 5000/5; uts zfstestbox 4.9.75-gentoo #8 SMP Wed Apr 4 17:58:36 EDT 2018 x86_64
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@async_destroy=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@empty_bpobj=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@lz4_compress=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@multi_vdev_crash_dump=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@spacemap_histogram=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@enabled_txg=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@hole_birth=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@extensible_dataset=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@embedded_data=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@bookmarks=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@large_blocks=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@large_dnode=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@sha512=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@skein=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@edonr=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@userobj_accounting=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@encryption=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@project_quota=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@device_removal=enabled
1523923647   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@obsolete_counts=enabled
1523923647   spa_history.c:309:spa_history_log_sync(): command: zpool create -f testpool loop0 loop1 loop2
1523923647   spa_history.c:317:spa_history_log_sync(): txg 6 create testpool/testfs (id 144) 
1523923647   spa_history.c:342:spa_history_log_sync(): ioctl create
1523923647   spa_history.c:309:spa_history_log_sync(): command: zfs create testpool/testfs
1523923647   spa_history.c:317:spa_history_log_sync(): txg 9 set testpool/testfs (id 144) mountpoint=/var/tmp/testdir
1523923647   spa_history.c:309:spa_history_log_sync(): command: zfs set mountpoint=/var/tmp/testdir testpool/testfs
1523923670   vdev_removal.c:313:vdev_remove_initiate_sync(): starting removal thread for vdev 0 (ffff880039b60000) in txg 33 im_obj=183
1523923670   spa_history.c:322:spa_history_log_sync(): txg 33 vdev remove started testpool vdev 0 /dev/loop0
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 72 segments for metaslab 0
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 24 segments for metaslab 1
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 2
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 3
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 4
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 5
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 2 segments for metaslab 6
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 4 segments for metaslab 7
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 8
1523923670   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 9
1523923671   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 10
1523923671   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 11
1523923671   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 12
1523923671   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 2 segments for metaslab 13
1523923671   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 14
1523923673   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 15
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 16
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 17
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 2 segments for metaslab 18
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 1 segments for metaslab 19
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 5 segments for metaslab 20
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 35 segments for metaslab 21
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 22
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 23
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 25
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 26
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 27
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 28
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 29
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 30
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 31
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 32
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 33
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 34
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 35
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 36
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 37
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 38
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 39
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 40
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 41
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 42
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 43
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 44
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 45
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 46
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 47
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 48
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 49
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 50
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 51
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 52
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 53
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 54
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 55
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 56
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 57
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 58
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 59
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 60
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 61
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 62
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 63
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 64
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 65
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 66
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 67
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 69
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 70
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 71
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 72
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 73
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 74
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 75
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 76
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 77
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 78
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 79
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 80
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 81
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 82
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 83
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 84
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 85
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 86
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 87
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 88
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 89
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 90
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 91
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 92
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 93
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 94
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 95
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 96
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 97
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 98
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 99
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 100
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 101
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 102
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 103
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 104
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 105
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 106
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 107
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 108
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 109
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 110
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 111
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 113
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 114
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 115
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 116
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 117
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 118
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 119
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 120
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 121
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 122
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 123
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 124
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 125
1523923674   vdev_removal.c:1248:spa_vdev_remove_thread(): copying 0 segments for metaslab 126
1523923674   vdev_indirect_mapping.c:495:vdev_indirect_mapping_add_entries(): txg 34: wrote 458 entries to indirect mapping obj 183; max offset=0x2afad800
=================================================================
 End of zfs_dbgmsg log
=================================================================
NOTE: Performing test-fail callback (/home/testuser/zfs/tests/zfs-tests/callbacks/zfs_dmesg.ksh)
=================================================================
 Tailing last 200 lines of dmesg log
=================================================================
[ 2593.948738] sd 6:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[ 2593.949850] sd 6:0:0:0: [sda] Write Protect is off
[ 2593.949852] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 2593.951894] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 2593.976925]  sda: sda1 sda9
[ 2593.985384] sd 6:0:0:0: [sda] Attached SCSI disk
[ 2606.114030]  sda: sda1 sda9
[ 2606.133608]  sda: sda1 sda9
[ 2606.664581] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 2607.041818] scsi 6:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[ 2607.052639] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 2607.054601] sd 6:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[ 2607.055716] sd 6:0:0:0: [sda] Write Protect is off
[ 2607.055718] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 2607.057751] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 2607.082059]  sda: sda1 sda9
[ 2607.090373] sd 6:0:0:0: [sda] Attached SCSI disk
[ 2618.177091]  sda: sda1 sda9
[ 2618.195876]  sda: sda1 sda9
[ 2618.216136]  sda: sda1 sda9
[ 2618.808892] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 2643.446100] scsi 6:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[ 2643.455603] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 2643.457637] sd 6:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[ 2643.458759] sd 6:0:0:0: [sda] Write Protect is off
[ 2643.458761] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 2643.460799] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 2643.483272]  sda: sda1 sda9
[ 2643.491714] sd 6:0:0:0: [sda] Attached SCSI disk
[ 2650.790623]  sda: sda1 sda9
[ 2650.809911]  sda: sda1 sda9
[ 2651.286779] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 2665.122201] scsi 6:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[ 2665.132658] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 2665.134679] sd 6:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[ 2665.135774] sd 6:0:0:0: [sda] Write Protect is off
[ 2665.135776] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 2665.137817] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 2665.161033]  sda: sda1 sda9
[ 2665.170078] sd 6:0:0:0: [sda] Attached SCSI disk
[ 2668.943528]  sda: sda1 sda9
[ 2668.963143]  sda: sda1 sda9
[ 2669.423383] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 2670.454182] scsi 6:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[ 2670.464630] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 2670.466633] sd 6:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[ 2670.467757] sd 6:0:0:0: [sda] Write Protect is off
[ 2670.467758] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 2670.469782] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 2670.494657]  sda: sda1 sda9
[ 2670.504566] sd 6:0:0:0: [sda] Attached SCSI disk
[ 2691.431360] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 2862.580747] hrtimer: interrupt took 2311821 ns
[ 3814.065915] scsi host6: scsi_debug: version 1.86 [20160430]
                 dev_size_mb=256, opts=0x0, submit_queues=1, statistics=0
[ 3814.066399] scsi 6:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[ 3814.078652] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 3814.080602] sd 6:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[ 3814.081745] sd 6:0:0:0: [sda] Write Protect is off
[ 3814.081747] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 3814.083799] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 3814.105097] sd 6:0:0:0: [sda] Attached SCSI disk
[ 3814.567273]  sda: sda1 sda9
[ 3814.586884]  sda: sda1 sda9
[ 3814.607600]  sda: sda1 sda9
[ 3815.521207] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 3817.398915] scsi 6:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[ 3817.409674] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 3817.411712] sd 6:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[ 3817.412822] sd 6:0:0:0: [sda] Write Protect is off
[ 3817.412823] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 3817.414871] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 3817.437041]  sda: sda1 sda9
[ 3817.445294] sd 6:0:0:0: [sda] Attached SCSI disk
[ 3822.156834] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 3822.277571] scsi host6: scsi_debug: version 1.86 [20160430]
                 dev_size_mb=256, opts=0x0, submit_queues=1, statistics=0
[ 3822.277777] scsi 6:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[ 3822.288609] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 3822.290561] sd 6:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[ 3822.291645] sd 6:0:0:0: [sda] Write Protect is off
[ 3822.291647] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 3822.293687] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 3822.314491] sd 6:0:0:0: [sda] Attached SCSI disk
[ 3823.027223]  sda: sda1 sda9
[ 3823.045952]  sda: sda1 sda9
[ 3823.064504]  sda: sda1 sda9
[ 3823.823367] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 3827.246544] scsi host6: scsi_debug: version 1.86 [20160430]
                 dev_size_mb=256, opts=0x0, submit_queues=1, statistics=0
[ 3827.246793] scsi 6:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[ 3827.256577] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 3827.258604] sd 6:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[ 3827.259743] sd 6:0:0:0: [sda] Write Protect is off
[ 3827.259745] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 3827.261814] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 3827.283234] sd 6:0:0:0: [sda] Attached SCSI disk
[ 3828.002539]  sda: sda1 sda9
[ 3828.264533]  sda: sda1 sda9
[ 3828.284439]  sda: sda1 sda9
[ 3828.666040]  sda: sda1 sda9
[ 3828.685167]  sda: sda1 sda9
[ 3829.004767]  sda: sda1 sda9
[ 3829.023644]  sda: sda1 sda9
[ 3829.401093]  sda: sda1 sda9
[ 3829.420061]  sda: sda1 sda9
[ 3834.053783] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 3908.490493] scsi host6: scsi_debug: version 1.86 [20160430]
                 dev_size_mb=96, opts=0x0, submit_queues=1, statistics=0
[ 3908.490747] scsi 6:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[ 3908.499622] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 3908.501645] sd 6:0:0:0: [sda] 196608 512-byte logical blocks: (101 MB/96.0 MiB)
[ 3908.501646] sd 6:0:0:0: [sda] 4096-byte physical blocks
[ 3908.502753] sd 6:0:0:0: [sda] Write Protect is off
[ 3908.502754] sd 6:0:0:0: [sda] Mode Sense: 73 00 10 08
[ 3908.504837] sd 6:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 3908.525747] sd 6:0:0:0: [sda] Attached SCSI disk
[ 3908.891709]  sda: sda1 sda9
[ 3908.911540]  sda: sda1 sda9
[ 3924.958169] sd 6:0:0:0: [sda] Synchronizing SCSI cache
[ 4150.218779] udevd[28350]: inotify_add_watch(7, /dev/loop0p6, 10) failed: No such file or directory
[ 4150.218986] udevd[28348]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4150.219388] udevd[22708]: inotify_add_watch(7, /dev/loop0p5, 10) failed: No such file or directory
[ 4150.219871] udevd[28351]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4150.220570] udevd[28352]: inotify_add_watch(7, /dev/loop0p3, 10) failed: No such file or directory
[ 4150.221101] udevd[28349]: inotify_add_watch(7, /dev/loop0p4, 10) failed: No such file or directory
[ 4150.223640] udevd[22708]: inotify_add_watch(7, /dev/loop0p5, 10) failed: No such file or directory
[ 4150.224394] udevd[28352]: inotify_add_watch(7, /dev/loop0p3, 10) failed: No such file or directory
[ 4150.224940] udevd[28348]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4150.225646] udevd[28350]: inotify_add_watch(7, /dev/loop0p6, 10) failed: No such file or directory
[ 4168.667990] udevd[25578]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4168.671142] udevd[25578]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4168.673678] udevd[25578]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4190.247907] udevd[17867]: inotify_add_watch(7, /dev/loop0p3, 10) failed: No such file or directory
[ 4190.247932] udevd[17869]: inotify_add_watch(7, /dev/loop0p4, 10) failed: No such file or directory
[ 4190.248762] udevd[17404]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4190.249137] udevd[17399]: inotify_add_watch(7, /dev/loop0p5, 10) failed: No such file or directory
[ 4190.249620] udevd[17866]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4190.251929] udevd[17867]: inotify_add_watch(7, /dev/loop0p3, 10) failed: No such file or directory
[ 4190.254904] udevd[17399]: inotify_add_watch(7, /dev/loop0p5, 10) failed: No such file or directory
[ 4190.255273] udevd[17866]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4190.256322] udevd[17867]: inotify_add_watch(7, /dev/loop0p3, 10) failed: No such file or directory
[ 4190.257201] udevd[17869]: inotify_add_watch(7, /dev/loop0p4, 10) failed: No such file or directory
[ 4234.545502] zd0: detected capacity change from 67108864 to 33554432
[ 4369.919652] udevd[2412]: inotify_add_watch(7, /dev/loop0p4, 10) failed: No such file or directory
[ 4369.920479] udevd[2415]: inotify_add_watch(7, /dev/loop0p5, 10) failed: No such file or directory
[ 4369.921676] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4369.922018] udevd[2413]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4369.923329] udevd[2414]: inotify_add_watch(7, /dev/loop0p3, 10) failed: No such file or directory
[ 4369.924747] udevd[2415]: inotify_add_watch(7, /dev/loop0p5, 10) failed: No such file or directory
[ 4369.925292] udevd[2412]: inotify_add_watch(7, /dev/loop0p4, 10) failed: No such file or directory
[ 4369.925939] udevd[2413]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4369.927179] udevd[2414]: inotify_add_watch(7, /dev/loop0p3, 10) failed: No such file or directory
[ 4370.124967] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4375.005494] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4375.015037] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4375.036123] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4376.916720] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4376.919601] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4377.120652] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4377.136302] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4377.325340] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4377.335691] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4377.352460] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4381.729747] udevd[3910]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4381.731789] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4381.908696] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4381.919995] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4382.099564] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4382.106925] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4389.004697] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4389.004768] udevd[3910]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4389.013372] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4389.014206] udevd[3910]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4389.191283] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4389.202420] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4389.368898] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4389.379319] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4390.923125] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4390.924317] udevd[3910]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4394.354807] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4394.357328] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4394.546179] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4394.558381] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4394.736489] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4394.750348] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4394.762118] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4397.828616] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4397.831548] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4398.034077] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4401.170745] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4401.172175] udevd[3910]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4401.174279] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[ 4401.174572] udevd[3910]: inotify_add_watch(7, /dev/loop0p2, 10) failed: No such file or directory
[ 4401.351672] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4401.365558] udevd[2409]: inotify_add_watch(7, /dev/loop1p1, 10) failed: No such file or directory
[ 4401.546582] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4401.558246] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4401.575243] udevd[2409]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[ 4404.544842] udevd[2409]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
=================================================================
 End of dmesg log
=================================================================
NOTE: Performing test-fail callback (/home/testuser/zfs/tests/zfs-tests/callbacks/zfs_mmp.ksh)
NOTE: Performing local cleanup via log_onexit (default_cleanup_noexit)
SUCCESS: zpool destroy -f testpool
SUCCESS: rm -rf /var/tmp/testdir
bunder2015 commented 6 years ago

I've done a few more runs and haven't had a reoccurrence yet. False alarm?

loli10K commented 6 years ago

I've only been able to reproduce this on a second run of the ZTS with $TESTPOOL still available and mounted on $TESTDIR from the (interrupted) first run. This doesn't seem to be reproducible on a "clean" builder.

bunder2015 commented 6 years ago

That might be possible. I'll close this for now unless I see it again.

bunder2015 commented 6 years ago

I'm afraid I have to reopen this, I've had this fail twice today unfortunately.

First fail was at random, but I decided to run the removal group 25 times. It happened on the third loop of running the removal group. edit: 8 of 25 loops failed

Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [00:58] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:21] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [00:37] [FAIL]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:17] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [00:34] [FAIL]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [00:30] [FAIL]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:21] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [00:42] [FAIL]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:14] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:25] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:09] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [00:35] [FAIL]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:19] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:12] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:29] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [00:35] [FAIL]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:30] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:33] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:11] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [00:44] [FAIL]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:09] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:14] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:09] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [01:19] [PASS]
Test: /home/testuser/zfs/tests/zfs-tests/tests/functional/removal/removal_with_export (run as root) [00:38] [FAIL]
stale[bot] commented 4 years ago

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.