search

openzfs / zfs

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

Possible kernel memory corruption after filled filesystem condition (buggy .next function procfs_list_seq_next [spl]) #10984

Closed aerusso closed 4 years ago

aerusso commented 4 years ago

System information

Type Version/Name
Distribution Name Debian
Distribution Version unstable
Linux Kernel 5.8 (both "5.8.7-1" and "5.8.10-1" version in Debian unstable) and 5.7 ("5.7.17-1") (I only tested these 3).
Architecture amd64
ZFS Version 0.8.5-staging (ed4c72525955fcf26b9ffca2c9df1f5e0c9fe530)

Describe the problem you're observing

rsend test failures when re-running the full ZTS suite.

Describe how to reproduce the problem

  1. (optional) Run the rsend_014_pos test. (This should succeed. There are furthermore no dmesg log messages with the word "buggy" in them. )
  2. Run the write_dirs_001_pos test from tests/functional/write_dirs (and the associated setup and cleanup steps). (This should succeed)
  3. Run the rsend_014_pos test (again with the setup and cleanup steps). This fails.

I get this kernel complaint:

seq_file: buggy .next function procfs_list_seq_next [spl] did not update position index

The above is the only reason I think there's memory corruption. I have seen no indication of data corruption anywhere else.

Include any warning/errors/backtraces from the system logs

Here is the ZTS log from the failing rsend test:

Test: /usr/share/zfs/zfs-tests/tests/functional/rsend/setup (run as root) [00:02] [PASS]
14:29:38.97 SUCCESS: zpool create testpool loop0
14:29:39.16 SUCCESS: zpool create testpool2 loop1
14:29:39.35 SUCCESS: zpool create testpool3 loop2
14:29:39.35 SUCCESS: mkdir /tmp/x/backdir-rsend /tmp/x/testdir
14:29:39.42 SUCCESS: zfs create -p testpool/testfs/fs1/fs2
14:29:39.43 SUCCESS: zfs snapshot testpool@psnap
14:29:39.45 SUCCESS: zfs clone testpool@psnap testpool/pclone
14:29:39.48 SUCCESS: zfs create -V 16M testpool/vol
14:29:39.50 SUCCESS: zfs create -V 16M testpool/testfs/vol
14:29:40.29 SUCCESS: zfs snapshot testpool/testfs/vol@vsnap
14:29:40.31 SUCCESS: zfs clone testpool/testfs/vol@vsnap testpool/testfs/vclone
14:29:41.13 SUCCESS: snapshot_tree testpool/testfs/fs1/fs2@fsnap
14:29:41.16 SUCCESS: zfs clone testpool/testfs/fs1/fs2@fsnap testpool/testfs/fs1/fclone
14:29:41.18 SUCCESS: zfs snapshot -r testpool@init
14:29:41.20 SUCCESS: snapshot_tree testpool@snapA
14:29:41.22 SUCCESS: snapshot_tree testpool@snapC
14:29:41.25 SUCCESS: snapshot_tree testpool/pclone@snapB
14:29:41.27 SUCCESS: snapshot_tree testpool/testfs@snapB
14:29:41.29 SUCCESS: snapshot_tree testpool/testfs@snapC
14:29:41.32 SUCCESS: snapshot_tree testpool/testfs/fs1@snapA
14:29:41.40 SUCCESS: snapshot_tree testpool/testfs/fs1@snapB
14:29:41.43 SUCCESS: snapshot_tree testpool/testfs/fs1@snapC
14:29:41.45 SUCCESS: snapshot_tree testpool/testfs/fs1/fclone@snapA
14:29:41.47 SUCCESS: zfs snapshot testpool/vol@snapA
14:29:41.48 SUCCESS: zfs snapshot testpool/testfs/vol@snapB
14:29:41.49 SUCCESS: zfs snapshot testpool/testfs/vol@snapC
14:29:41.51 SUCCESS: zfs snapshot testpool/testfs/vclone@snapC
14:29:41.53 SUCCESS: zfs snapshot -r testpool@final
14:29:41.53 SUCCESS: setup_test_model testpool
Test: /usr/share/zfs/zfs-tests/tests/functional/rsend/rsend_014_pos (run as root) [00:00] [FAIL]
14:29:41.56 ASSERTION: zfs send will work on filesystems and volumes in a read-only pool.
14:29:41.75 SUCCESS: zpool export testpool
14:29:41.96 cannot import 'testpool': no such pool available
14:29:41.96 ERROR: zpool import -o readonly=on testpool exited 1
14:29:41.96 NOTE: Performing test-fail callback (/usr/share/zfs/zfs-tests/callbacks/zfs_dbgmsg.ksh)
14:29:41.96 =================================================================
14:29:41.96  Tailing last 200 lines of zfs_dbgmsg log
14:29:41.96 =================================================================
14:29:41.97 timestamp    message 
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 create pool version 5000; software version unknown; uts hydra 5.8.0-2-amd64 #1 SMP Debian 5.8.10-1 (2020-09-19) x86_64
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@async_destroy=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@empty_bpobj=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@lz4_compress=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@multi_vdev_crash_dump=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_histogram=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@enabled_txg=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@hole_birth=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@extensible_dataset=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@embedded_data=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmarks=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@filesystem_limits=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_blocks=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_dnode=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@sha512=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@skein=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@edonr=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@userobj_accounting=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@encryption=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@project_quota=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@device_removal=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@obsolete_counts=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@zpool_checkpoint=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_v2=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@allocation_classes=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@resilver_defer=enabled
14:29:41.97 1601152178   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmark_v2=enabled
14:29:41.97 1601152178   mmp.c:240:mmp_thread_start(): MMP thread started pool 'testpool' gethrtime 1447124391594
14:29:41.97 1601152178   spa_history.c:305:spa_history_log_sync(): command: zpool create testpool loop0
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 create pool version 5000; software version unknown; uts hydra 5.8.0-2-amd64 #1 SMP Debian 5.8.10-1 (2020-09-19) x86_64
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@async_destroy=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@empty_bpobj=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@lz4_compress=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@multi_vdev_crash_dump=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_histogram=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@enabled_txg=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@hole_birth=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@extensible_dataset=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@embedded_data=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmarks=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@filesystem_limits=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_blocks=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_dnode=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@sha512=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@skein=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@edonr=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@userobj_accounting=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@encryption=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@project_quota=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@device_removal=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@obsolete_counts=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@zpool_checkpoint=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_v2=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@allocation_classes=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@resilver_defer=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmark_v2=enabled
14:29:41.97 1601152179   mmp.c:240:mmp_thread_start(): MMP thread started pool 'testpool2' gethrtime 1447318161538
14:29:41.97 1601152179   spa_history.c:305:spa_history_log_sync(): command: zpool create testpool2 loop1
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 create pool version 5000; software version unknown; uts hydra 5.8.0-2-amd64 #1 SMP Debian 5.8.10-1 (2020-09-19) x86_64
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@async_destroy=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@empty_bpobj=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@lz4_compress=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@multi_vdev_crash_dump=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_histogram=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@enabled_txg=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@hole_birth=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@extensible_dataset=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@embedded_data=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmarks=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@filesystem_limits=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_blocks=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@large_dnode=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@sha512=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@skein=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@edonr=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@userobj_accounting=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@encryption=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@project_quota=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@device_removal=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@obsolete_counts=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@zpool_checkpoint=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@spacemap_v2=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@allocation_classes=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@resilver_defer=enabled
14:29:41.97 1601152179   spa_history.c:316:spa_history_log_sync(): txg 4 set feature@bookmark_v2=enabled
14:29:41.97 1601152179   mmp.c:240:mmp_thread_start(): MMP thread started pool 'testpool3' gethrtime 1447508808588
14:29:41.97 1601152179   spa_history.c:305:spa_history_log_sync(): command: zpool create testpool3 loop2
14:29:41.97 1601152179   spa_history.c:309:spa_history_log_sync(): txg 8 create testpool/testfs (id 259) 
14:29:41.97 1601152179   spa_history.c:338:spa_history_log_sync(): ioctl create
14:29:41.97 1601152179   spa_history.c:309:spa_history_log_sync(): txg 9 create testpool/testfs/fs1 (id 70) 
14:29:41.97 1601152179   spa_history.c:338:spa_history_log_sync(): ioctl create
14:29:41.97 1601152179   spa_history.c:309:spa_history_log_sync(): txg 10 create testpool/testfs/fs1/fs2 (id 387) 
14:29:41.97 1601152179   spa_history.c:338:spa_history_log_sync(): ioctl create
14:29:41.97 1601152179   spa_history.c:305:spa_history_log_sync(): command: zfs create -p testpool/testfs/fs1/fs2
14:29:41.97 1601152179   spa_history.c:309:spa_history_log_sync(): txg 11 snapshot testpool@psnap (id 512) 
14:29:41.97 1601152179   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152179   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool@psnap
14:29:41.97 1601152179   spa_history.c:309:spa_history_log_sync(): txg 12 clone testpool/pclone (id 517) origin=testpool@psnap (512)
14:29:41.97 1601152179   spa_history.c:338:spa_history_log_sync(): ioctl clone
14:29:41.97 1601152179   spa_history.c:305:spa_history_log_sync(): command: zfs clone testpool@psnap testpool/pclone
14:29:41.97 1601152179   spa_history.c:309:spa_history_log_sync(): txg 13 create testpool/vol (id 644) 
14:29:41.97 1601152179   spa_history.c:309:spa_history_log_sync(): txg 14 set testpool/vol (id 644) refreservation=19398656
14:29:41.97 1601152179   spa_history.c:338:spa_history_log_sync(): ioctl create
14:29:41.97 1601152179   spa_history.c:305:spa_history_log_sync(): command: zfs create -V 16M testpool/vol
14:29:41.97 1601152179   spa_history.c:309:spa_history_log_sync(): txg 15 create testpool/testfs/vol (id 76) 
14:29:41.97 1601152179   spa_history.c:309:spa_history_log_sync(): txg 16 set testpool/testfs/vol (id 76) refreservation=19398656
14:29:41.97 1601152180   spa_history.c:338:spa_history_log_sync(): ioctl create
14:29:41.97 1601152180   spa_history.c:305:spa_history_log_sync(): command: zfs create -V 16M testpool/testfs/vol
14:29:41.97 1601152180   spa_history.c:309:spa_history_log_sync(): txg 17 snapshot testpool/testfs/vol@vsnap (id 768) 
14:29:41.97 1601152180   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152180   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs/vol@vsnap
14:29:41.97 1601152180   spa_history.c:309:spa_history_log_sync(): txg 18 clone testpool/testfs/vclone (id 899) origin=testpool/testfs/vol@vsnap (768)
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl clone
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs clone testpool/testfs/vol@vsnap testpool/testfs/vclone
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 19 snapshot testpool/testfs/fs1/fs2@fsnap (id 79) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs/fs1/fs2@fsnap
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 20 clone testpool/testfs/fs1/fclone (id 266) origin=testpool/testfs/fs1/fs2@fsnap (79)
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl clone
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs clone testpool/testfs/fs1/fs2@fsnap testpool/testfs/fs1/fclone
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 21 snapshot testpool@init (id 81) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 21 snapshot testpool/testfs@init (id 83) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 21 snapshot testpool/testfs/vclone@init (id 85) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 21 snapshot testpool/testfs/vol@init (id 87) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 21 snapshot testpool/testfs/fs1@init (id 89) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 21 snapshot testpool/testfs/fs1/fs2@init (id 91) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 21 snapshot testpool/testfs/fs1/fclone@init (id 93) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 21 snapshot testpool/vol@init (id 95) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 21 snapshot testpool/pclone@init (id 97) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot -r testpool@init
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 22 snapshot testpool@snapA (id 522) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool@snapA
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 23 snapshot testpool@snapC (id 99) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool@snapC
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 24 snapshot testpool/pclone@snapB (id 770) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/pclone@snapB
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 25 snapshot testpool/testfs@snapB (id 102) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs@snapB
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 26 snapshot testpool/testfs@snapC (id 105) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs@snapC
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 27 snapshot testpool/testfs/fs1@snapA (id 525) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs/fs1@snapA
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 28 snapshot testpool/testfs/fs1@snapB (id 772) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs/fs1@snapB
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 29 snapshot testpool/testfs/fs1@snapC (id 648) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs/fs1@snapC
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 30 snapshot testpool/testfs/fs1/fclone@snapA (id 393) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs/fs1/fclone@snapA
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 31 snapshot testpool/vol@snapA (id 276) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/vol@snapA
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 32 snapshot testpool/testfs/vol@snapB (id 650) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs/vol@snapB
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 33 snapshot testpool/testfs/vol@snapC (id 904) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs/vol@snapC
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 34 snapshot testpool/testfs/vclone@snapC (id 652) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot testpool/testfs/vclone@snapC
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 35 snapshot testpool@final (id 654) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 35 snapshot testpool/testfs@final (id 656) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 35 snapshot testpool/testfs/vclone@final (id 658) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 35 snapshot testpool/testfs/vol@final (id 660) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 35 snapshot testpool/testfs/fs1@final (id 662) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 35 snapshot testpool/testfs/fs1/fs2@final (id 664) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 35 snapshot testpool/testfs/fs1/fclone@final (id 666) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 35 snapshot testpool/vol@final (id 668) 
14:29:41.97 1601152181   spa_history.c:309:spa_history_log_sync(): txg 35 snapshot testpool/pclone@final (id 670) 
14:29:41.97 1601152181   spa_history.c:338:spa_history_log_sync(): ioctl snapshot
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zfs snapshot -r testpool@final
14:29:41.97 1601152181   spa_history.c:305:spa_history_log_sync(): command: zpool export testpool
14:29:41.97 1601152181   spa_misc.c:407:spa_load_note(): spa_load(testpool, config trusted): UNLOADING
14:29:41.97 1601152181   mmp.c:260:mmp_thread_stop(): MMP thread stopped pool 'testpool' gethrtime 1449902867532
14:29:41.97 =================================================================
14:29:41.97  End of zfs_dbgmsg log
14:29:41.97 =================================================================
14:29:41.97 NOTE: Performing test-fail callback (/usr/share/zfs/zfs-tests/callbacks/zfs_dmesg.ksh)
14:29:41.97 =================================================================
14:29:41.97  Tailing last 200 lines of dmesg log
14:29:41.97 =================================================================
14:29:41.98 [    3.880780] systemd[1]: Condition check resulted in Load Kernel Module drm being skipped.
14:29:41.98 [    3.881705] systemd[1]: Starting nftables...
14:29:41.98 [    3.881981] systemd[1]: plymouth-switch-root.service: Succeeded.
14:29:41.98 [    3.882342] systemd[1]: Stopped Plymouth switch root service.
14:29:41.98 [    3.883300] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
14:29:41.98 [    3.883355] systemd[1]: Stopped Journal Service.
14:29:41.98 [    3.884314] systemd[1]: Listening on Syslog Socket.
14:29:41.98 [    3.886488] systemd[1]: Starting Journal Service...
14:29:41.98 [    3.888337] systemd[1]: Starting Load Kernel Modules...
14:29:41.98 [    3.889620] systemd[1]: Starting Remount Root and Kernel File Systems...
14:29:41.98 [    3.891140] systemd[1]: Starting Coldplug All udev Devices...
14:29:41.98 [    3.893432] systemd[1]: sysroot.mount: Succeeded.
14:29:41.98 [    3.894397] systemd[1]: Mounted Huge Pages File System.
14:29:41.98 [    3.894681] systemd[1]: Mounted POSIX Message Queue File System.
14:29:41.98 [    3.895693] systemd[1]: Mounted Kernel Debug File System.
14:29:41.98 [    3.896859] systemd[1]: Mounted Kernel Trace File System.
14:29:41.98 [    3.898365] systemd[1]: Finished Set the console keyboard layout.
14:29:41.98 [    3.899554] systemd[1]: Finished Create list of static device nodes for the current kernel.
14:29:41.98 [    3.899934] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
14:29:41.98 [    3.901585] systemd[1]: Finished Load Kernel Modules.
14:29:41.98 [    3.902199] systemd[1]: Finished Remount Root and Kernel File Systems.
14:29:41.98 [    3.902993] systemd[1]: Condition check resulted in FUSE Control File System being skipped.
14:29:41.98 [    3.903101] systemd[1]: Condition check resulted in Kernel Configuration File System being skipped.
14:29:41.98 [    3.905599] systemd[1]: Starting Rebuild Hardware Database...
14:29:41.98 [    3.905731] systemd[1]: Condition check resulted in Platform Persistent Storage Archival being skipped.
14:29:41.98 [    3.906825] systemd[1]: Starting Load/Save Random Seed...
14:29:41.98 [    3.908069] systemd[1]: Starting Apply Kernel Variables...
14:29:41.98 [    3.909643] systemd[1]: Starting Create System Users...
14:29:41.98 [    3.918750] systemd[1]: Finished Apply Kernel Variables.
14:29:41.98 [    3.920642] systemd[1]: Finished Load/Save Random Seed.
14:29:41.98 [    3.927399] systemd[1]: Finished Create System Users.
14:29:41.98 [    3.928747] systemd[1]: Starting Create Static Device Nodes in /dev...
14:29:41.98 [    3.932632] RPC: Registered named UNIX socket transport module.
14:29:41.98 [    3.932633] RPC: Registered udp transport module.
14:29:41.98 [    3.932634] RPC: Registered tcp transport module.
14:29:41.98 [    3.932634] RPC: Registered tcp NFSv4.1 backchannel transport module.
14:29:41.98 [    3.933840] systemd[1]: Mounted RPC Pipe File System.
14:29:41.98 [    3.935040] systemd[1]: Starting pNFS block layout mapping daemon...
14:29:41.98 [    3.937385] systemd[1]: Started pNFS block layout mapping daemon.
14:29:41.98 [    3.942482] systemd[1]: Finished Create Static Device Nodes in /dev.
14:29:41.98 [    3.942638] systemd[1]: Reached target Local File Systems (Pre).
14:29:41.98 [    3.944191] systemd[1]: Starting File System Check on /dev/disk/by-uuid/E0AA-B2A5...
14:29:41.98 [    3.951271] systemd[1]: Started File System Check Daemon to report status.
14:29:41.98 [    3.970919] systemd[1]: Finished File System Check on /dev/disk/by-uuid/E0AA-B2A5.
14:29:41.98 [    3.972322] systemd[1]: Mounting /boot/efi...
14:29:41.98 [    3.978680] systemd[1]: Finished Coldplug All udev Devices.
14:29:41.98 [    3.980193] systemd[1]: Starting Helper to synchronize boot up for ifupdown...
14:29:41.98 [    3.981363] systemd[1]: Starting Wait for udev To Complete Device Initialization...
14:29:41.98 [    3.984212] systemd[1]: Finished Helper to synchronize boot up for ifupdown.
14:29:41.98 [    3.984632] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
14:29:41.98 [    3.985734] systemd[1]: Mounted NFSD configuration filesystem.
14:29:41.98 [    3.989692] systemd[1]: Mounted /boot/efi.
14:29:41.98 [    4.159374] systemd[1]: Started Journal Service.
14:29:41.98 [    4.389362] input: Power Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/device:01/PNP0C0C:00/input/input3
14:29:41.98 [    4.389395] ACPI: Power Button [PWRB]
14:29:41.98 [    4.391558] ACPI: AC Adapter [ACAD] (on-line)
14:29:41.98 [    4.392098] input: Sleep Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/device:01/PNP0C0E:00/input/input4
14:29:41.98 [    4.392124] ACPI: Sleep Button [SLPB]
14:29:41.98 [    4.392200] input: Lid Switch as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0D:00/input/input5
14:29:41.98 [    4.392251] ACPI: Lid Switch [LID0]
14:29:41.98 [    4.392305] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input6
14:29:41.98 [    4.392360] ACPI: Power Button [PWRF]
14:29:41.98 [    4.432564] input: Ideapad extra buttons as /devices/pci0000:00/0000:00:1f.0/PNP0C09:00/VPC2004:00/input/input7
14:29:41.98 [    4.463346] ACPI Warning: SystemIO range 0x0000000000000428-0x000000000000042F conflicts with OpRegion 0x0000000000000400-0x000000000000047F (\PMIO) (20200528/utaddress-204)
14:29:41.98 [    4.463353] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
14:29:41.98 [    4.463355] ACPI Warning: SystemIO range 0x0000000000000540-0x000000000000054F conflicts with OpRegion 0x0000000000000500-0x0000000000000563 (\GPIO) (20200528/utaddress-204)
14:29:41.98 [    4.463359] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
14:29:41.98 [    4.463360] ACPI Warning: SystemIO range 0x0000000000000530-0x000000000000053F conflicts with OpRegion 0x0000000000000500-0x0000000000000563 (\GPIO) (20200528/utaddress-204)
14:29:41.98 [    4.463363] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
14:29:41.98 [    4.463363] ACPI Warning: SystemIO range 0x0000000000000500-0x000000000000052F conflicts with OpRegion 0x0000000000000500-0x0000000000000563 (\GPIO) (20200528/utaddress-204)
14:29:41.98 [    4.463366] ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
14:29:41.98 [    4.463367] lpc_ich: Resource conflict(s) found affecting gpio_ich
14:29:41.98 [    4.469144] sd 1:0:0:0: Attached scsi generic sg0 type 0
14:29:41.98 [    4.469199] sr 2:0:0:0: Attached scsi generic sg1 type 5
14:29:41.98 [    4.470399] EFI Variables Facility v0.08 2004-May-17
14:29:41.98 [    4.471413] input: PC Speaker as /devices/platform/pcspkr/input/input8
14:29:41.98 [    4.472446] alx 0000:01:00.0 eth0: Qualcomm Atheros AR816x/AR817x Ethernet [dc:0e:a1:f1:29:f2]
14:29:41.98 [    4.474452] i801_smbus 0000:00:1f.3: SMBus using PCI interrupt
14:29:41.98 [    4.474875] i2c i2c-7: 2/2 memory slots populated (from DMI)
14:29:41.98 [    4.476004] i2c i2c-7: Successfully instantiated SPD at 0x50
14:29:41.98 [    4.560339] pstore: Using crash dump compression: deflate
14:29:41.98 [    4.560346] pstore: Registered efi as persistent store backend
14:29:41.98 [    4.560447] RAPL PMU: API unit is 2^-32 Joules, 3 fixed counters, 163840 ms ovfl timer
14:29:41.98 [    4.560448] RAPL PMU: hw unit of domain pp0-core 2^-16 Joules
14:29:41.98 [    4.560449] RAPL PMU: hw unit of domain package 2^-16 Joules
14:29:41.98 [    4.560451] RAPL PMU: hw unit of domain pp1-gpu 2^-16 Joules
14:29:41.98 [    4.561987] cfg80211: Loading compiled-in X.509 certificates for regulatory database
14:29:41.98 [    4.562281] cfg80211: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf'
14:29:41.98 [    4.562588] cfg80211: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328'
14:29:41.98 [    4.562909] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
14:29:41.98 [    4.563788] platform regulatory.0: firmware: direct-loading firmware regulatory.db
14:29:41.98 [    4.564678] platform regulatory.0: firmware: direct-loading firmware regulatory.db.p7s
14:29:41.98 [    4.616859] Intel(R) Wireless WiFi driver for Linux
14:29:41.98 [    4.617135] iwlwifi 0000:02:00.0: can't disable ASPM; OS doesn't have ASPM control
14:29:41.98 [    4.619877] alx 0000:01:00.0 enp1s0: renamed from eth0
14:29:41.98 [    4.622385] iwlwifi 0000:02:00.0: firmware: direct-loading firmware iwlwifi-2000-6.ucode
14:29:41.98 [    4.622562] iwlwifi 0000:02:00.0: loaded firmware version 18.168.6.1 2000-6.ucode op_mode iwldvm
14:29:41.98 [    4.622581] iwlwifi 0000:02:00.0: firmware: failed to load iwl-debug-yoyo.bin (-2)
14:29:41.98 [    4.623632] firmware_class: See https://wiki.debian.org/Firmware for information about missing firmware
14:29:41.98 [    4.656100] at24 7-0050: supply vcc not found, using dummy regulator
14:29:41.98 [    4.657675] at24 7-0050: 256 byte spd EEPROM, read-only
14:29:41.98 [    4.658139] iTCO_vendor_support: vendor-support=0
14:29:41.98 [    4.665770] snd_hda_intel 0000:00:1b.0: bound 0000:00:02.0 (ops i915_audio_component_bind_ops [i915])
14:29:41.98 [    4.666733] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.11
14:29:41.98 [    4.666767] iTCO_wdt: Found a Panther Point TCO device (Version=2, TCOBASE=0x0460)
14:29:41.98 [    4.666875] iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0)
14:29:41.98 [    4.687817] snd_hda_codec_realtek hdaudioC0D0: autoconfig for ALC269VC: line_outs=1 (0x14/0x0/0x0/0x0/0x0) type:speaker
14:29:41.98 [    4.687819] snd_hda_codec_realtek hdaudioC0D0:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
14:29:41.98 [    4.687820] snd_hda_codec_realtek hdaudioC0D0:    hp_outs=1 (0x15/0x0/0x0/0x0/0x0)
14:29:41.98 [    4.687820] snd_hda_codec_realtek hdaudioC0D0:    mono: mono_out=0x0
14:29:41.98 [    4.687821] snd_hda_codec_realtek hdaudioC0D0:    dig-out=0x1e/0x0
14:29:41.98 [    4.687822] snd_hda_codec_realtek hdaudioC0D0:    inputs:
14:29:41.98 [    4.687823] snd_hda_codec_realtek hdaudioC0D0:      Mic=0x18
14:29:41.98 [    4.687824] snd_hda_codec_realtek hdaudioC0D0:      Internal Mic=0x12
14:29:41.98 [    4.752121] input: HDA Digital PCBeep as /devices/pci0000:00/0000:00:1b.0/sound/card0/input10
14:29:41.98 [    4.752165] input: HDA Intel PCH Mic as /devices/pci0000:00/0000:00:1b.0/sound/card0/input11
14:29:41.98 [    4.752202] input: HDA Intel PCH Headphone as /devices/pci0000:00/0000:00:1b.0/sound/card0/input12
14:29:41.98 [    4.752239] input: HDA Intel PCH HDMI/DP,pcm=3 as /devices/pci0000:00/0000:00:1b.0/sound/card0/input13
14:29:41.98 [    4.759114] iwlwifi 0000:02:00.0: CONFIG_IWLWIFI_DEBUG disabled
14:29:41.98 [    4.759116] iwlwifi 0000:02:00.0: CONFIG_IWLWIFI_DEBUGFS disabled
14:29:41.98 [    4.759117] iwlwifi 0000:02:00.0: CONFIG_IWLWIFI_DEVICE_TRACING disabled
14:29:41.98 [    4.759118] iwlwifi 0000:02:00.0: Detected Intel(R) Centrino(R) Wireless-N 2200 BGN, REV=0x104
14:29:41.98 [    4.794751] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
14:29:41.98 [    4.797956] iwlwifi 0000:02:00.0 wlp2s0: renamed from wlan0
14:29:41.98 [    4.834083] intel_rapl_common: Found RAPL domain package
14:29:41.98 [    4.834085] intel_rapl_common: Found RAPL domain core
14:29:41.98 [    4.834086] intel_rapl_common: Found RAPL domain uncore
14:29:41.98 [    4.834091] intel_rapl_common: RAPL package-0 domain package locked by BIOS
14:29:41.98 [    5.991745] psmouse serio1: synaptics: queried max coordinates: x [..5702], y [..4730]
14:29:41.98 [    6.078880] psmouse serio1: synaptics: queried min coordinates: x [1242..], y [1124..]
14:29:41.98 [    6.146782] mc: Linux media interface: v0.10
14:29:41.98 [    6.153060] alg: No test for fips(ansi_cprng) (fips_ansi_cprng)
14:29:41.98 [    6.161651] videodev: Linux video capture interface: v2.00
14:29:41.98 [    6.216349] Bluetooth: Core ver 2.22
14:29:41.98 [    6.216361] NET: Registered protocol family 31
14:29:41.98 [    6.216362] Bluetooth: HCI device and connection manager initialized
14:29:41.98 [    6.216365] Bluetooth: HCI socket layer initialized
14:29:41.98 [    6.216366] Bluetooth: L2CAP socket layer initialized
14:29:41.98 [    6.216369] Bluetooth: SCO socket layer initialized
14:29:41.98 [    6.253024] psmouse serio1: synaptics: Touchpad model: 1, fw: 8.1, id: 0x1e2b1, caps: 0xd00123/0x840300/0x123c00/0x0, board id: 2023, fw id: 980150
14:29:41.98 [    6.335511] uvcvideo: Found UVC 1.00 device Lenovo EasyCamera (13d3:5162)
14:29:41.98 [    6.352472] uvcvideo 3-1.6:1.0: Entity type for entity Extension 4 was not initialized!
14:29:41.98 [    6.352477] uvcvideo 3-1.6:1.0: Entity type for entity Processing 2 was not initialized!
14:29:41.98 [    6.352479] uvcvideo 3-1.6:1.0: Entity type for entity Camera 1 was not initialized!
14:29:41.98 [    6.352670] input: Lenovo EasyCamera: Lenovo EasyC as /devices/pci0000:00/0000:00:1d.0/usb3/3-1/3-1.6/3-1.6:1.0/input/input14
14:29:41.98 [    6.352909] usbcore: registered new interface driver uvcvideo
14:29:41.98 [    6.352911] USB Video Class driver (1.1.1)
14:29:41.98 [    6.361218] input: SynPS/2 Synaptics TouchPad as /devices/platform/i8042/serio1/input/input9
14:29:41.98 [    6.364983] usbcore: registered new interface driver btusb
14:29:41.98 [    6.474465] Bluetooth: hci0: BCM: chip id 63
14:29:41.98 [    6.475510] Bluetooth: hci0: BCM: features 0x07
14:29:41.98 [    6.492474] Bluetooth: hci0: hydra
14:29:41.98 [    6.492481] Bluetooth: hci0: BCM20702A1 (001.002.014) build 0000
14:29:41.98 [    6.494530] bluetooth hci0: firmware: failed to load brcm/BCM20702A1-0489-e042.hcd (-2)
14:29:41.98 [    6.496443] bluetooth hci0: firmware: failed to load brcm/BCM-0489-e042.hcd (-2)
14:29:41.98 [    6.498352] Bluetooth: hci0: BCM: firmware Patch file not found, tried:
14:29:41.98 [    6.500357] Bluetooth: hci0: BCM: 'brcm/BCM20702A1-0489-e042.hcd'
14:29:41.98 [    6.502213] Bluetooth: hci0: BCM: 'brcm/BCM-0489-e042.hcd'
14:29:41.98 [    6.543402] spl: loading out-of-tree module taints kernel.
14:29:41.98 [    6.543627] spl: module verification failed: signature and/or required key missing - tainting kernel
14:29:41.98 [    6.549180] znvpair: module license 'CDDL' taints kernel.
14:29:41.98 [    6.549182] Disabling lock debugging due to kernel taint
14:29:41.98 [    8.214457] ZFS: Loaded module v0.8.5~g10-1, ZFS pool version 5000, ZFS filesystem version 5
14:29:41.98 [    8.275926] audit: type=1400 audit(1601150739.769:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/bin/less" pid=954 comm="apparmor_parser"
14:29:41.98 [    8.279234] audit: type=1400 audit(1601150739.773:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-senddoc" pid=957 comm="apparmor_parser"
14:29:41.98 [    8.279925] audit: type=1400 audit(1601150739.773:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-xpdfimport" pid=962 comm="apparmor_parser"
14:29:41.98 [    8.280455] audit: type=1400 audit(1601150739.773:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=960 comm="apparmor_parser"
14:29:41.98 [    8.280459] audit: type=1400 audit(1601150739.773:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod" pid=960 comm="apparmor_parser"
14:29:41.98 [    8.281943] audit: type=1400 audit(1601150739.777:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/apt-cacher-ng" pid=955 comm="apparmor_parser"
14:29:41.98 [    8.282803] audit: type=1400 audit(1601150739.777:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="traceroute" pid=958 comm="apparmor_parser"
14:29:41.98 [    8.283026] audit: type=1400 audit(1601150739.777:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="syslog-ng" pid=953 comm="apparmor_parser"
14:29:41.98 [    8.283376] audit: type=1400 audit(1601150739.777:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="mdnsd" pid=959 comm="apparmor_parser"
14:29:41.98 [    8.283867] audit: type=1400 audit(1601150739.777:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nscd" pid=963 comm="apparmor_parser"
14:29:41.98 [    8.769224] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
14:29:41.98 [    8.769226] Bluetooth: BNEP filters: protocol multicast
14:29:41.98 [    8.769229] Bluetooth: BNEP socket layer initialized
14:29:41.98 [    8.780271] NET: Registered protocol family 38
14:29:41.98 [    9.217832] iwlwifi 0000:02:00.0: Radio type=0x2-0x0-0x0
14:29:41.98 [    9.502038] iwlwifi 0000:02:00.0: Radio type=0x2-0x0-0x0
14:29:41.98 [    9.592280] iwlwifi 0000:02:00.0: Radio type=0x2-0x0-0x0
14:29:41.98 [    9.875418] iwlwifi 0000:02:00.0: Radio type=0x2-0x0-0x0
14:29:41.98 [    9.885651] NFSD: Using UMH upcall client tracking operations.
14:29:41.98 [    9.885656] NFSD: starting 90-second grace period (net f0000098)
14:29:41.98 [   10.545598] iwlwifi 0000:02:00.0: Radio type=0x2-0x0-0x0
14:29:41.98 [   10.821920] iwlwifi 0000:02:00.0: Radio type=0x2-0x0-0x0
14:29:41.98 [   11.509357] wlp2s0: authenticate with d4:5d:64:0b:c3:50
14:29:41.98 [   11.512961] wlp2s0: send auth to d4:5d:64:0b:c3:50 (try 1/3)
14:29:41.98 [   11.515714] wlp2s0: authenticated
14:29:41.98 [   11.516543] wlp2s0: associate with d4:5d:64:0b:c3:50 (try 1/3)
14:29:41.98 [   11.520426] wlp2s0: RX AssocResp from d4:5d:64:0b:c3:50 (capab=0x1411 status=0 aid=1)
14:29:41.98 [   11.540969] wlp2s0: associated
14:29:41.98 [   11.570797] IPv6: ADDRCONF(NETDEV_CHANGE): wlp2s0: link becomes ready
14:29:41.98 [   12.124983] Bluetooth: RFCOMM TTY layer initialized
14:29:41.98 [   12.124991] Bluetooth: RFCOMM socket layer initialized
14:29:41.98 [   12.124996] Bluetooth: RFCOMM ver 1.11
14:29:41.98 [ 1311.736488] loop: module loaded
14:29:41.98 [ 1312.399076] seq_file: buggy .next function procfs_list_seq_next [spl] did not update position index
14:29:41.98 [ 1323.394774] device-mapper: uevent: version 1.0.3
14:29:41.98 [ 1323.394833] device-mapper: ioctl: 4.42.0-ioctl (2020-02-27) initialised: dm-devel@redhat.com
14:29:41.98 [ 1450.216344] seq_file: buggy .next function procfs_list_seq_next [spl] did not update position index
14:29:41.98 =================================================================
14:29:41.98  End of dmesg log
14:29:41.98 =================================================================
14:29:41.98 NOTE: Performing test-fail callback (/usr/share/zfs/zfs-tests/callbacks/zfs_mmp.ksh)
14:29:41.98 NOTE: Performing local cleanup via log_onexit (cleanup_pool testpool2)
14:29:41.99 SUCCESS: rm -rf /tmp/x/backdir-rsend/*
14:29:41.99 SUCCESS: zfs destroy -Rf testpool2
Test: /usr/share/zfs/zfs-tests/tests/functional/rsend/cleanup (run as root) [00:00] [PASS]
14:29:42.05 NOTE: Pool does not exist. (testpool)
14:29:42.13 SUCCESS: zpool destroy -f testpool2
14:29:42.20 SUCCESS: zpool destroy -f testpool3
14:29:42.20 SUCCESS: rm -rf /tmp/x/backdir-rsend /tmp/x/testdir
behlendorf commented 4 years ago

@aerusso thanks for noticing this. The warning is harmless, I've opened #10996 to address it.