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: zfs_share_005_pos #7379

Closed bunder2015 closed 6 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 0.7.0-401_g10adee27c
SPL Version 0.7.0-31_g43983eb

Describe the problem you're observing

test case fails with nfs-utils 2.3.1-r3 but succeeds with 1.3.4-r1, the former was recently stabilized by gentoo

Describe how to reproduce the problem

run tests

Include any warning/errors/backtraces from the system logs

ASSERTION: Verify that NFS share options are propagated correctly.
SUCCESS: zfs set sharenfs=off testpool/testfs
SUCCESS: zfs set sharenfs=ro testpool/testfs
SUCCESS: zfs set sharenfs=rw testpool/testfs
SUCCESS: zfs set sharenfs=rw,insecure testpool/testfs
The 'insecure' option was not found in share output.
NOTE: Performing test-fail callback (/home/testuser/zfs/tests/zfs-tests/callbacks/zfs_dbgmsg.ksh)
=================================================================
 Tailing last 200 lines of zfs_dbgmsg log
=================================================================
1522621315   spa_history.c:317:spa_history_log_sync(): txg 657 set testpool (id 54) recordsize=1024
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=1024 testpool
1522621315   spa_history.c:317:spa_history_log_sync(): txg 658 set testpool (id 54) recordsize=2048
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=2048 testpool
1522621315   spa_history.c:317:spa_history_log_sync(): txg 659 set testpool (id 54) recordsize=4096
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=4096 testpool
1522621315   spa_history.c:317:spa_history_log_sync(): txg 660 set testpool (id 54) recordsize=8192
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=8192 testpool
1522621315   spa_history.c:317:spa_history_log_sync(): txg 661 set testpool (id 54) recordsize=16384
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=16384 testpool
1522621315   spa_history.c:317:spa_history_log_sync(): txg 662 set testpool (id 54) recordsize=32768
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=32768 testpool
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=65536 testpool
1522621315   spa_history.c:317:spa_history_log_sync(): txg 664 set testpool (id 54) recordsize=131072
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=131072 testpool
1522621315   spa_history.c:317:spa_history_log_sync(): txg 665 set testpool/testfs (id 259) recordsize=512
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recordsize=512 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 666 set testpool/testfs (id 259) recordsize=1024
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recordsize=1024 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 667 set testpool/testfs (id 259) recordsize=2048
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recordsize=2048 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 668 set testpool/testfs (id 259) recordsize=4096
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recordsize=4096 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 669 set testpool/testfs (id 259) recordsize=8192
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recordsize=8192 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 670 set testpool/testfs (id 259) recordsize=16384
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recordsize=16384 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 671 set testpool/testfs (id 259) recordsize=32768
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recordsize=32768 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 672 set testpool/testfs (id 259) recordsize=65536
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recordsize=65536 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 673 set testpool/testfs (id 259) recordsize=131072
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recordsize=131072 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 674 set testpool/testfs (id 259) recordsize=512
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=512 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 675 set testpool/testfs (id 259) recordsize=1024
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=1024 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 676 set testpool/testfs (id 259) recordsize=2048
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=2048 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 677 set testpool/testfs (id 259) recordsize=4096
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=4096 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 678 set testpool/testfs (id 259) recordsize=8192
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=8192 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 679 set testpool/testfs (id 259) recordsize=16384
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=16384 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 680 set testpool/testfs (id 259) recordsize=32768
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=32768 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 681 set testpool/testfs (id 259) recordsize=65536
1522621315   spa_history.c:309:spa_history_log_sync(): command: zfs set recsize=65536 testpool/testfs
1522621315   spa_history.c:317:spa_history_log_sync(): txg 682 set testpool/testfs (id 259) recordsize=131072
1522621315   spa_history.c:317:spa_history_log_sync(): txg 684 set testpool/testfs (id 259) mountpoint=legacy
1522621316   spa_history.c:309:spa_history_log_sync(): command: zfs set mountpoint=legacy testpool/testfs
1522621316   spa_history.c:317:spa_history_log_sync(): txg 697 set testpool/testfs (id 259) mountpoint=/var/tmp/testdir
1522621316   spa_history.c:309:spa_history_log_sync(): command: zfs set mountpoint=/var/tmp/testdir testpool/testfs
1522621316   spa_history.c:317:spa_history_log_sync(): txg 698 snapshot testpool/testfs@testsnap (id 414) 
1522621316   spa_history.c:342:spa_history_log_sync(): ioctl snapshot
1522621316   spa_history.c:309:spa_history_log_sync(): command: zfs snapshot testpool/testfs@testsnap
1522621316   spa_history.c:317:spa_history_log_sync(): txg 699 snapshot testpool/testvol@testsnap (id 416) 
1522621316   spa_history.c:342:spa_history_log_sync(): ioctl snapshot
1522621316   spa_history.c:309:spa_history_log_sync(): command: zfs snapshot testpool/testvol@testsnap
1522621332   spa_history.c:309:spa_history_log_sync(): command: zpool list -Ho freeing testpool
1522621342   spa_history.c:309:spa_history_log_sync(): command: zfs get -pH -o value compressratio testpool/testctr/testfs1
1522621342   spa_history.c:309:spa_history_log_sync(): command: zfs get -pH -o value origin testpool/testctr/testfs1
1522621352   spa_history.c:309:spa_history_log_sync(): command: zfs get -pH -o value sharenfs testpool/testfs@testsnap
1522621367   spa_history.c:309:spa_history_log_sync(): command: zpool list -Ho freeing testpool
1522621367   spa_history.c:309:spa_history_log_sync(): command: zfs get -pH -o value mounted testpool/testvol@testsnap
1522621373   spa_history.c:309:spa_history_log_sync(): command: zfs get -pH -o value recordsize testpool/testvol@testsnap
1522621373   spa_history.c:309:spa_history_log_sync(): command: zfs get -pH -o value reservation testpool/testvol@testsnap
1522621383   zcp.c:671:zcp_debug(): txg 716 ZCP: snap: testpool/testvol@testsnap errno: 0
1522621383   spa_history.c:317:spa_history_log_sync(): txg 716 destroy testpool/testvol@testsnap (id 416) 
1522621383   spa_history.c:342:spa_history_log_sync(): ioctl destroy_snaps
1522621383   spa_history.c:309:spa_history_log_sync(): command: zfs destroy testpool/testvol@testsnap
1522621383   spa_history.c:309:spa_history_log_sync(): command: zfs get name testpool/testfs@testsnap
1522621383   zcp.c:671:zcp_debug(): txg 717 ZCP: snap: testpool/testfs@testsnap errno: 0
1522621383   spa_history.c:317:spa_history_log_sync(): txg 717 destroy testpool/testfs@testsnap (id 414) 
1522621383   spa_history.c:342:spa_history_log_sync(): ioctl destroy_snaps
1522621383   spa_history.c:309:spa_history_log_sync(): command: zfs destroy testpool/testfs@testsnap
1522621383   spa_history.c:317:spa_history_log_sync(): txg 718 set testpool/testfs (id 259) keylocation=none
1522621383   spa_history.c:309:spa_history_log_sync(): command: zfs set keylocation=none testpool/testfs
1522621383   spa_history.c:317:spa_history_log_sync(): txg 719 create testpool/testfs1 (id 292) 
1522621383   spa_history.c:317:spa_history_log_sync(): txg 720 set testpool/testfs1 (id 292) keylocation=file:///testpool/pkey
1522621384   spa_history.c:342:spa_history_log_sync(): ioctl create
1522621384   spa_history.c:309:spa_history_log_sync(): command: zfs create -o encryption=on -o keyformat=passphrase -o keylocation=file:///testpool/pkey testpool/testfs1
1522621384   spa_history.c:317:spa_history_log_sync(): txg 721 set testpool/testfs1 (id 292) keylocation=file:///testpool/pkey
1522621384   spa_history.c:309:spa_history_log_sync(): command: zfs set keylocation=file:///testpool/pkey testpool/testfs1
1522621384   spa_history.c:317:spa_history_log_sync(): txg 722 set testpool/testfs1 (id 292) keylocation=prompt
1522621384   spa_history.c:309:spa_history_log_sync(): command: zfs set keylocation=prompt testpool/testfs1
1522621384   spa_history.c:342:spa_history_log_sync(): ioctl unload-key
1522621384   spa_history.c:309:spa_history_log_sync(): command: zfs unload-key testpool/testfs1
1522621384   spa_history.c:309:spa_history_log_sync(): command: zfs load-key testpool/testfs1
1522621384   spa_history.c:317:spa_history_log_sync(): txg 724 create testpool/testfs1/child (id 181) 
1522621384   spa_history.c:342:spa_history_log_sync(): ioctl create
1522621384   spa_history.c:309:spa_history_log_sync(): command: zfs create testpool/testfs1/child
1522621384   spa_history.c:317:spa_history_log_sync(): txg 726 destroy testpool/testfs1/child (id 181) 
1522621384   bptree.c:232:bptree_iterate(): bptree index 0: traversing from min_txg=1 bookmark 0/0/0/0
1522621384   dsl_scan.c:3109:dsl_scan_sync(): freed 18 blocks in 0ms from free_bpobj/bptree txg 726; err=0
1522621384   spa_history.c:317:spa_history_log_sync(): txg 729 destroy testpool/testfs1 (id 292) 
1522621384   bptree.c:232:bptree_iterate(): bptree index 0: traversing from min_txg=1 bookmark 0/0/0/0
1522621384   dsl_scan.c:3109:dsl_scan_sync(): freed 18 blocks in 0ms from free_bpobj/bptree txg 729; err=0
1522621384   spa_history.c:309:spa_history_log_sync(): command: zfs destroy -r testpool/testfs1
1522621384   spa_history.c:317:spa_history_log_sync(): txg 731 destroy testpool/testctr/testfs1 (id 77) 
1522621384   bptree.c:232:bptree_iterate(): bptree index 0: traversing from min_txg=1 bookmark 0/0/0/0
1522621384   dsl_scan.c:3109:dsl_scan_sync(): freed 18 blocks in 0ms from free_bpobj/bptree txg 731; err=0
1522621384   spa_history.c:309:spa_history_log_sync(): command: zfs destroy -R testpool/testctr/testfs1
1522621384   spa_history.c:317:spa_history_log_sync(): txg 732 destroy testpool/testctr (id 71) 
1522621384   bptree.c:232:bptree_iterate(): bptree index 0: traversing from min_txg=1 bookmark 0/0/0/0
1522621384   dsl_scan.c:3109:dsl_scan_sync(): freed 18 blocks in 0ms from free_bpobj/bptree txg 732; err=0
1522621384   spa_history.c:309:spa_history_log_sync(): command: zfs destroy -Rf testpool/testctr
1522621384   spa_history.c:309:spa_history_log_sync(): command: zpool destroy -f testpool
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 create pool version 5000; software version 5000/5; uts zfstestbox 4.9.75-gentoo #2 SMP Thu Jan 18 18:32:56 EST 2018 x86_64
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@async_destroy=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@empty_bpobj=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@lz4_compress=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@multi_vdev_crash_dump=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@spacemap_histogram=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@enabled_txg=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@hole_birth=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@extensible_dataset=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@embedded_data=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@bookmarks=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@filesystem_limits=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@large_blocks=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@large_dnode=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@sha512=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@skein=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@edonr=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@userobj_accounting=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@encryption=enabled
1522621385   spa_history.c:322:spa_history_log_sync(): txg 4 set feature@project_quota=enabled
1522621385   spa_history.c:309:spa_history_log_sync(): command: zpool create -f testpool loop0
1522621385   spa_history.c:342:spa_history_log_sync(): ioctl create
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs create testpool/testfs
1522621385   spa_history.c:317:spa_history_log_sync(): txg 10 set testpool/testfs (id 67) mountpoint=/var/tmp/testdir
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs set mountpoint=/var/tmp/testdir testpool/testfs
1522621385   spa_history.c:317:spa_history_log_sync(): txg 11 create testpool/testctr (id 259) 
1522621385   spa_history.c:342:spa_history_log_sync(): ioctl create
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs create testpool/testctr
1522621385   spa_history.c:317:spa_history_log_sync(): txg 13 set testpool/testctr (id 259) canmount=0
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs set canmount=off testpool/testctr
1522621385   spa_history.c:317:spa_history_log_sync(): txg 14 create testpool/testctr/testfs1 (id 265) 
1522621385   spa_history.c:342:spa_history_log_sync(): ioctl create
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs create testpool/testctr/testfs1
1522621385   spa_history.c:317:spa_history_log_sync(): txg 16 set testpool/testctr/testfs1 (id 265) mountpoint=/var/tmp/testdir1
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs set mountpoint=/var/tmp/testdir1 testpool/testctr/testfs1
1522621385   spa_history.c:317:spa_history_log_sync(): txg 17 create testpool/testvol (id 74) 
1522621385   spa_history.c:317:spa_history_log_sync(): txg 19 set testpool/testvol (id 74) refreservation=164364288
1522621385   spa_history.c:342:spa_history_log_sync(): ioctl create
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs create -V 150m testpool/testvol
1522621385   spa_history.c:317:spa_history_log_sync(): txg 22 snapshot testpool/testfs@snapshot (id 268) 
1522621385   spa_history.c:342:spa_history_log_sync(): ioctl snapshot
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs snapshot testpool/testfs@snapshot
1522621385   spa_history.c:317:spa_history_log_sync(): txg 23 clone testpool/testfs-clone (id 273) origin=testpool/testfs@snapshot (268)
1522621385   spa_history.c:342:spa_history_log_sync(): ioctl clone
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs clone testpool/testfs@snapshot testpool/testfs-clone
1522621385   spa_history.c:317:spa_history_log_sync(): txg 25 set testpool/testfs-clone (id 273) mountpoint=/var/tmp/testdir2
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs set mountpoint=/var/tmp/testdir2 testpool/testfs-clone
1522621385   spa_history.c:317:spa_history_log_sync(): txg 26 set testpool/testctr/testfs1 (id 265) sharenfs=on
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=on testpool/testctr/testfs1
1522621385   spa_history.c:317:spa_history_log_sync(): txg 27 set testpool/testfs-clone (id 273) sharenfs=on
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=on testpool/testfs-clone
1522621385   spa_history.c:317:spa_history_log_sync(): txg 28 set testpool/testfs (id 67) sharenfs=on
1522621385   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=on testpool/testfs
1522621385   spa_history.c:317:spa_history_log_sync(): txg 29 set testpool/testctr/testfs1 (id 265) sharenfs=off
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=off testpool/testctr/testfs1
1522621386   spa_history.c:317:spa_history_log_sync(): txg 30 set testpool/testfs-clone (id 273) sharenfs=off
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=off testpool/testfs-clone
1522621386   spa_history.c:317:spa_history_log_sync(): txg 31 set testpool/testfs (id 67) sharenfs=off
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=off testpool/testfs
1522621386   spa_history.c:317:spa_history_log_sync(): txg 33 destroy testpool/testfs-clone (id 273) 
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs destroy -f testpool/testfs-clone
1522621386   zcp.c:671:zcp_debug(): txg 34 ZCP: snap: testpool/testfs@snapshot errno: 0
1522621386   spa_history.c:317:spa_history_log_sync(): txg 34 destroy testpool/testfs@snapshot (id 268) 
1522621386   spa_history.c:342:spa_history_log_sync(): ioctl destroy_snaps
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs destroy -f testpool/testfs@snapshot
1522621386   spa_history.c:317:spa_history_log_sync(): txg 35 set testpool/testfs (id 67) sharenfs=off
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=off testpool/testfs
1522621386   spa_history.c:317:spa_history_log_sync(): txg 36 set testpool/testctr/testfs1 (id 265) sharenfs=off
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=off testpool/testctr/testfs1
1522621386   spa_history.c:317:spa_history_log_sync(): txg 37 inherit testpool/testfs (id 67) sharenfs=off
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs inherit -r sharenfs testpool/testfs
1522621386   spa_history.c:317:spa_history_log_sync(): txg 38 inherit testpool/testctr/testfs1 (id 265) sharenfs=off
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs inherit -r sharenfs testpool/testctr/testfs1
1522621386   spa_history.c:317:spa_history_log_sync(): txg 39 snapshot testpool/testfs@snapshot (id 384) 
1522621386   spa_history.c:342:spa_history_log_sync(): ioctl snapshot
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs snapshot testpool/testfs@snapshot
1522621386   spa_history.c:317:spa_history_log_sync(): txg 40 set testpool/testfs (id 67) sharenfs=on
1522621386   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=on testpool/testfs
1522621386   zcp.c:671:zcp_debug(): txg 41 ZCP: snap: testpool/testfs@snapshot errno: 0
1522621386   spa_history.c:317:spa_history_log_sync(): txg 41 destroy testpool/testfs@snapshot (id 384) 
1522621387   spa_history.c:342:spa_history_log_sync(): ioctl destroy_snaps
1522621387   spa_history.c:309:spa_history_log_sync(): command: zfs destroy testpool/testfs@snapshot
1522621387   spa_history.c:317:spa_history_log_sync(): txg 42 set testpool/testfs (id 67) sharenfs=off
1522621387   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=off testpool/testfs
1522621387   spa_history.c:317:spa_history_log_sync(): txg 43 set testpool/testfs (id 67) sharenfs=off
1522621387   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=off testpool/testfs
1522621387   spa_history.c:317:spa_history_log_sync(): txg 44 set testpool/testfs (id 67) sharenfs=ro
1522621387   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=ro testpool/testfs
1522621387   spa_history.c:317:spa_history_log_sync(): txg 45 set testpool/testfs (id 67) sharenfs=rw
1522621387   spa_history.c:309:spa_history_log_sync(): command: zfs set sharenfs=rw testpool/testfs
1522621387   spa_history.c:317:spa_history_log_sync(): txg 46 set testpool/testfs (id 67) sharenfs=rw,insecure
=================================================================
 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
=================================================================
[    0.333932] ACPI: PCI Interrupt Link [GSIA] enabled at IRQ 16
[    0.334464] ACPI: PCI Interrupt Link [GSIB] enabled at IRQ 17
[    0.334979] ACPI: PCI Interrupt Link [GSIC] enabled at IRQ 18
[    0.335473] ACPI: PCI Interrupt Link [GSID] enabled at IRQ 19
[    0.335892] PCI: CLS 0 bytes, default 64
[    0.335951] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    0.335954] software IO TLB [mem 0x7bfd9000-0x7ffd9000] (64MB) mapped at [ffff88007bfd9000-ffff88007ffd8fff]
[    0.336357] Scanning for low memory corruption every 60 seconds
[    0.336394] simple-framebuffer simple-framebuffer.0: framebuffer at 0xf4000000, 0x300000 bytes, mapped to 0xffffc90001800000
[    0.336398] simple-framebuffer simple-framebuffer.0: format=a8r8g8b8, mode=1024x768x32, linelength=4096
[    0.337955] Console: switching to colour frame buffer device 128x48
[    0.339106] simple-framebuffer simple-framebuffer.0: fb0: simplefb registered!
[    0.340007] audit: initializing netlink subsys (disabled)
[    0.340049] audit: type=2000 audit(1522620533.415:1): initialized
[    0.340216] workingset: timestamp_bits=56 max_order=20 bucket_order=0
[    0.340540] NFS: Registering the id_resolver key type
[    0.340566] Key type id_resolver registered
[    0.340586] Key type id_legacy registered
[    0.340611] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.341865] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[    0.341888] io scheduler noop registered
[    0.341902] io scheduler deadline registered (default)
[    0.342179] ACPI: PCI Interrupt Link [GSIG] enabled at IRQ 22
[    0.352992] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.375166] 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[    0.375534] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[    0.375557] ACPI: Power Button [PWRF]
[    0.375606] Warning: Processor Platform Limit event detected, but not handled.
[    0.375625] Consider compiling CPUfreq support into your kernel.
[    0.386548] [drm] Initialized
[    0.387140] ACPI: PCI Interrupt Link [GSIF] enabled at IRQ 21
[    0.387597] [drm] Device Version 0.0
[    0.387950] [drm] Compression level 0 log level 0
[    0.388279] [drm] Currently using mode #0, list at 0x488
[    0.388605] [drm] 12286 io pages at offset 0x1000000
[    0.388935] [drm] 16777216 byte draw area at offset 0x0
[    0.389256] [drm] RAM header offset: 0x3ffe000
[    0.389576] [drm] rom modes offset 0x488 for 128 modes
[    0.390000] [TTM] Zone  kernel: Available graphics memory: 2028644 kiB
[    0.390336] [TTM] Initializing pool allocator
[    0.390668] [TTM] Initializing DMA pool allocator
[    0.391011] [drm] qxl: 16M of VRAM memory size
[    0.391330] [drm] qxl: 63M of IO pages memory ready (VRAM domain)
[    0.391662] [drm] qxl: 64M of Surface memory size
[    0.614783] [drm] main mem slot 1 [f4000000,3ffe000]
[    0.615433] [drm] surface mem slot 2 [f8000000,4000000]
[    0.615767] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    0.616087] [drm] No driver support for vblank timestamp query.
[    0.616714] [drm] fb mappable at 0xF4000000, size 3145728
[    0.617032] [drm] fb: depth 24, pitch 4096, width 1024, height 768
[    0.617343] checking generic (f4000000 300000) vs hw (f4000000 1000000)
[    0.617343] fb: switching to qxldrmfb from simple
[    0.617666] Console: switching to colour dummy device 80x25
[    0.617777] fbcon: qxldrmfb (fb0) is primary device
[    0.642074] Console: switching to colour frame buffer device 128x48
[    0.643176] qxl 0000:00:01.0: fb0: qxldrmfb frame buffer device
[    0.647668] [drm] Initialized qxl 0.1.0 20120117 for 0000:00:01.0 on minor 0
[    0.649396] loop: module loaded
[    0.650909]  vda: vda1 vda2 vda3 vda4
[    0.651271] lpc_ich 0000:00:1f.0: I/O space for GPIO uninitialized
[    0.654013] scsi host0: scsi_debug: version 1.86 [20160430]
                 dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
[    0.654251] scsi 0:0:0:0: Direct-Access     Linux    scsi_debug       0186 PQ: 0 ANSI: 7
[    0.662787] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    0.662871] ahci 0000:00:1f.2: version 3.0
[    0.663329] ahci 0000:00:1f.2: AHCI 0001.0000 32 slots 6 ports 1.5 Gbps 0x3f impl SATA mode
[    0.663343] ahci 0000:00:1f.2: flags: 64bit ncq only 
[    0.664017] scsi host1: ahci
[    0.664106] scsi host2: ahci
[    0.664196] scsi host3: ahci
[    0.664292] scsi host4: ahci
[    0.664397] scsi host5: ahci
[    0.664498] scsi host6: ahci
[    0.664775] ata1: SATA max UDMA/133 abar m4096@0xfca18000 port 0xfca18100 irq 16
[    0.664794] sd 0:0:0:0: [sda] 16384 512-byte logical blocks: (8.39 MB/8.00 MiB)
[    0.665240] ata2: SATA max UDMA/133 abar m4096@0xfca18000 port 0xfca18180 irq 16
[    0.665476] ata3: SATA max UDMA/133 abar m4096@0xfca18000 port 0xfca18200 irq 16
[    0.665717] ata4: SATA max UDMA/133 abar m4096@0xfca18000 port 0xfca18280 irq 16
[    0.665851] sd 0:0:0:0: [sda] Write Protect is off
[    0.665852] sd 0:0:0:0: [sda] Mode Sense: 73 00 10 08
[    0.666171] ata5: SATA max UDMA/133 abar m4096@0xfca18000 port 0xfca18300 irq 16
[    0.666409] ata6: SATA max UDMA/133 abar m4096@0xfca18000 port 0xfca18380 irq 16
[    0.667308] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.667545] ehci-pci: EHCI PCI platform driver
[    0.667881] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[    0.668299] ehci-pci 0000:00:1d.7: EHCI Host Controller
[    0.668548] ehci-pci 0000:00:1d.7: new USB bus registered, assigned bus number 1
[    0.668908] ehci-pci 0000:00:1d.7: irq 19, io mem 0xfca17000
[    0.675698] ehci-pci 0000:00:1d.7: USB 2.0 started, EHCI 1.00
[    0.676175] hub 1-0:1.0: USB hub found
[    0.676453] hub 1-0:1.0: 6 ports detected
[    0.676930] uhci_hcd: USB Universal Host Controller Interface driver
[    0.677736] uhci_hcd 0000:00:1d.0: UHCI Host Controller
[    0.677991] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    0.678285] uhci_hcd 0000:00:1d.0: irq 16, io base 0x0000c060
[    0.678786] hub 2-0:1.0: USB hub found
[    0.679052] hub 2-0:1.0: 2 ports detected
[    0.680004] uhci_hcd 0000:00:1d.1: UHCI Host Controller
[    0.680249] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3
[    0.680551] uhci_hcd 0000:00:1d.1: irq 17, io base 0x0000c080
[    0.681063] hub 3-0:1.0: USB hub found
[    0.681336] hub 3-0:1.0: 2 ports detected
[    0.682202] uhci_hcd 0000:00:1d.2: UHCI Host Controller
[    0.682440] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4
[    0.682753] uhci_hcd 0000:00:1d.2: irq 18, io base 0x0000c0a0
[    0.683258] hub 4-0:1.0: USB hub found
[    0.683536] hub 4-0:1.0: 2 ports detected
[    0.683973] usbcore: registered new interface driver usb-storage
[    0.684316] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[    0.685324] serio: i8042 KBD port at 0x60,0x64 irq 1
[    0.685551] serio: i8042 AUX port at 0x60,0x64 irq 12
[    0.685850] mousedev: PS/2 mouse device common for all mice
[    0.686289] rtc_cmos 00:00: RTC can wake from S4
[    0.686875] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
[    0.687131] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[    0.687792] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram
[    0.688605] i801_smbus 0000:00:1f.3: SMBus using PCI interrupt
[    0.688974] sd 0:0:0:0: [sda] Attached SCSI disk
[    0.688988] md: raid0 personality registered for level 0
[    0.688989] md: raid1 personality registered for level 1
[    0.688989] md: raid10 personality registered for level 10
[    0.689040] md: raid6 personality registered for level 6
[    0.689040] md: raid5 personality registered for level 5
[    0.689041] md: raid4 personality registered for level 4
[    0.689320] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) initialised: dm-devel@redhat.com
[    0.689325] device-mapper: raid: Loading target version 1.9.1
[    0.689356] usbcore: registered new interface driver usbhid
[    0.689356] usbhid: USB HID core driver
[    0.689418] Initializing XFRM netlink socket
[    0.689424] NET: Registered protocol family 17
[    0.689452] Key type dns_resolver registered
[    0.689677] microcode: sig=0x306c1, pf=0x1, revision=0x1
[    0.689735] microcode: Microcode Update Driver: v2.01 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
[    0.689744] AVX2 version of gcm_enc/dec engaged.
[    0.689744] AES CTR mode by8 optimization enabled
[    0.690436] registered taskstats version 1
[    0.976033] ata4: SATA link down (SStatus 0 SControl 300)
[    0.976384] ata5: SATA link down (SStatus 0 SControl 300)
[    0.976725] ata2: SATA link down (SStatus 0 SControl 300)
[    0.977032] ata3: SATA link down (SStatus 0 SControl 300)
[    0.977340] ata6: SATA link down (SStatus 0 SControl 300)
[    0.977686] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    0.978021] ata1.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100
[    0.978244] ata1.00: applying bridge limits
[    0.978571] ata1.00: configured for UDMA/100
[    0.979093] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.5+ PQ: 0 ANSI: 5
[    0.989671] f 4026531845#5: failed to wait on release 5 after spincount 301
[    0.992895] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
[    0.993127] cdrom: Uniform CD-ROM driver Revision: 3.20
[    0.993465] sr 1:0:0:0: Attached scsi CD-ROM sr0
[    0.993531] sr 1:0:0:0: Attached scsi generic sg1 type 5
[    1.308386] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input3
[    1.309239] md: Waiting for all devices to be available before autodetect
[    1.309485] md: If you don't use raid, use raid=noautodetect
[    1.309917] md: Autodetecting RAID arrays.
[    1.310165] md: Scanned 0 and added 0 devices.
[    1.310400] md: autorun ...
[    1.310631] md: ... autorun DONE.
[    1.311073] EXT4-fs (vda3): mounting ext3 file system using the ext4 subsystem
[    1.320231] random: fast init done
[    1.327413] EXT4-fs (vda3): mounted filesystem with ordered data mode. Opts: (null)
[    1.327688] VFS: Mounted root (ext3 filesystem) readonly on device 253:3.
[    1.328395] devtmpfs: mounted
[    1.329426] Freeing unused kernel memory: 984K
[    1.329677] Write protecting the kernel read-only data: 10240k
[    1.330134] Freeing unused kernel memory: 284K
[    1.333437] Freeing unused kernel memory: 1852K
[    1.379690] tsc: Refined TSC clocksource calibration: 4000.095 MHz
[    1.379971] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x39a8b6b39d7, max_idle_ns: 440795295743 ns
[    2.008181] cgroup: cgroup2: unknown option "nsdelegate"
[    2.048148] udevd[1744]: starting version 3.2.5
[    2.070628] udevd[1745]: starting eudev-3.2.5
[    2.737697] EXT4-fs (vda3): re-mounted. Opts: (null)
[    2.790840] Adding 1048552k swap on /dev/vda4.  Priority:-1 extents:1 across:1048552k 
[   16.819661] random: crng init done
[   71.521970] sh (3375): drop_caches: 1
[   71.562930] spl: loading out-of-tree module taints kernel.
[   71.563469] SPL: Loaded module v0.7.0-31_g43983eb (DEBUG mode)
[   71.567087] SPLAT: Loaded module v0.7.0-31_g43983eb (DEBUG mode)
[   71.570122] zavl: module license 'CDDL' taints kernel.
[   71.570123] Disabling lock debugging due to kernel taint
[   73.498195] ZFS: Loaded module v0.7.0-401_g10adee27c (DEBUG mode), ZFS pool version 5000, ZFS filesystem version 5
[  238.297600] udevd[23887]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[  238.303608] udevd[23887]: inotify_add_watch(7, /dev/loop0p1, 10) failed: No such file or directory
[  238.311403] udevd[8190]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[  238.317143] udevd[23887]: inotify_add_watch(7, /dev/loop2p1, 10) failed: No such file or directory
[  552.306641] WARNING: Unable to automount /testpool/testclone/.zfs/snapshot/testsnap/testpool/testclone@testsnap: 256
[  552.972448] WARNING: Unable to automount /var/tmp/testdir/.zfs/snapshot/testsnap/testpool/testfs@testsnap: 256
[  630.870515] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  631.928768] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  632.896343] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  637.651280] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  641.876879] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  646.122916] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  648.403123] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  650.787872] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  652.632515] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  658.618549] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  664.249565] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
[  669.185739] EXT2-fs (zd0): warning: mounting unchecked fs, running e2fsck is recommended
=================================================================
 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 (cleanup)
SUCCESS: zfs set sharenfs=off testpool/testfs
loli10K commented 6 years ago

@bunder2015 was the NFS server started prior to running the test suite? That has to be done manually.

bunder2015 commented 6 years ago

Let me get back to you on this, I'm having problems with some of the zpool_reopen and fault tests now too.

bunder2015 commented 6 years ago

Yep, my fault, sorry.

loli10K commented 6 years ago

That's ok, i'm glad this got sorted out quickly. Thank you for testing on Gentoo, IIRC we were able to catch some issues that were not detected by the buildslaves thanks to the different version of Gentoo packages.