zfs recv PANIC at range_tree.c:304:range_tree_find_impl()

This change was made by a bot.

Can you describe the zfs environment and the command that was being actioned that triggered this issue?

The two machines involved are:

Receiver, bionic, probably running 4.15.0-76-generic and zfsutils-linux 0.7.5-1ubuntu16.7

Sender, focal, probably running 5.4.0-12-generic and zfsutils-linux 0.8.3-1ubuntu3

I'm using sanoid and syncoid to automate snapshot management and sending and receiving. The combination worked well for about a week before I got this failure.

These are just the zfs bookmark and zfs send commands from the sender.

These are all the zpool and zfs commands on the receiver except snapshots, renames, and destroys, associated with my Ubuntu archive mirror rsync. (7000-ish lines of juggling 30-snapshots. I should do something better here.)

What is interesting is the following commit modifies range_tree_clear() so it performs a zero size check and returns before calling range_tree_find_impl(). This commit is not in 18.10 and 19.04 Ubuntu ZFS releases.

commit a1d477c
Author: Matthew Ahrens <email address hidden>
Date: Thu Sep 22 09:30:13 2016 -0700

OpenZFS 7614, 9064 - zfs device evacuation/removal

OpenZFS 7614 - zfs device evacuation/removal
OpenZFS 9064 - remove_mirror should wait for device removal to complete

the specific change is:

@@ -560,6 +536,9 @@ range_tree_clear(range_tree_t *rt, uint64_t start, uint64_t size)
 {
        range_seg_t *rs;

+ if (size == 0)
+ return;
+
        while ((rs = range_tree_find_impl(rt, start, size)) != NULL) {
                uint64_t free_start = MAX(rs->rs_start, start);
                uint64_t free_end = MIN(rs->rs_end, start + size);

I'm not sure why this check was added, but I guess it handles the cases were zero sized allocations are allowed and stops these from doing any unnecessary clearing and avoids the assertion. But the semantics change is not clear in the commit message.

I've uploaded a potential fix to a PPA, do you mind testing this using the zfs-dkms kernel modules as follows:

sudo add-apt-repository ppa:colin-king/zfs-sru-1861235
sudo apt-get update
sudo apt-get install zfs-dkms

and reboot.

Then check the correct ZFS module is being used by:

dmesg | grep ZFS

It should be the 0.7.5-1ubuntu16.9~lp1861235 version.

And see if this helps avoid this issue.

Please ignore the above. Apparently the issue needs a little more digging and the workaround is insufficient.

In this scenario, dmu_object_free has been called and this calls dnode_free_range using dnode_free_range(dn, 0, DMU_OBJECT_END, tx)

In this case, in dnode_free_range len is DMU_OBJECT_ENDand offset is 0, so..:

    if (len == DMU_OBJECT_END) {
            len = UINT64_MAX - off;
            trunc = TRUE;
    }

makes len is UINT64_MAX and trunc = TRUE. If one follows the code through we have this stanza:

    blkid = off >> blkshift;
    nblks = len >> blkshift;
    if (trunc)
            nblks += 1;

and this is the last place nblks gets updated. This implies blkshift is zero, nblks = UINT64_MAX >> 0 is UINT64_MAX, trunc is TRUE so nblks +=1 wraps nblks back to 0, hence the assert later on.

For blkshift to be zero blksz dn->dn_datablksz is zero, so this looks like some form of corruption.

Incidentally, dnode_free_range hasn't changed much in the focal 8.2.x zfs, so I'm not sure if upgrading to that will make much of a difference.

BTW, Is this still and open issue?

*still an open issue?

Hello Colin, yes, this is still an open issue:

Linux wopr 4.15.0-91-generic #92-Ubuntu SMP Fri Feb 28 11:09:48 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

Apr 22 19:10:03 wopr zed[12576]: eid=8352 class=history_event pool_guid=0xB3B099B638F02EEF
Apr 22 19:10:03 wopr kernel: VERIFY(size != 0) failed
Apr 22 19:10:03 wopr kernel: PANIC at range_tree.c:304:range_tree_find_impl()
Apr 22 19:10:03 wopr kernel: Showing stack for process 12577
Apr 22 19:10:03 wopr kernel: CPU: 8 PID: 12577 Comm: receive_writer Tainted: P O 4.15.0-91-generic #92-Ubuntu
Apr 22 19:10:03 wopr kernel: Hardware name: Supermicro SSG-6038R-E1CR16L/X10DRH-iT, BIOS 2.0 12/17/2015
Apr 22 19:10:03 wopr kernel: Call Trace:
Apr 22 19:10:03 wopr kernel: dump_stack+0x6d/0x8e
Apr 22 19:10:03 wopr kernel: spl_dumpstack+0x42/0x50 [spl]
Apr 22 19:10:03 wopr kernel: spl_panic+0xc8/0x110 [spl]
Apr 22 19:10:03 wopr kernel: ? __switch_to_asm+0x41/0x70
Apr 22 19:10:03 wopr kernel: ? abd_iter_map+0xa/0x90 [zfs]
Apr 22 19:10:03 wopr kernel: ? dbuf_dirty+0x43d/0x850 [zfs]
Apr 22 19:10:03 wopr kernel: ? getrawmonotonic64+0x43/0xd0
Apr 22 19:10:03 wopr kernel: ? getrawmonotonic64+0x43/0xd0
Apr 22 19:10:03 wopr kernel: ? dmu_zfetch+0x49a/0x500 [zfs]
Apr 22 19:10:03 wopr kernel: ? getrawmonotonic64+0x43/0xd0
Apr 22 19:10:03 wopr kernel: ? dmu_zfetch+0x49a/0x500 [zfs]
Apr 22 19:10:03 wopr kernel: ? mutex_lock+0x12/0x40
Apr 22 19:10:03 wopr kernel: ? dbuf_rele_and_unlock+0x1a8/0x4b0 [zfs]
Apr 22 19:10:03 wopr kernel: range_tree_find_impl+0x88/0x90 [zfs]
Apr 22 19:10:03 wopr kernel: ? spl_kmem_zalloc+0xdc/0x1a0 [spl]
Apr 22 19:10:03 wopr kernel: range_tree_clear+0x4f/0x60 [zfs]
Apr 22 19:10:03 wopr kernel: dnode_free_range+0x11f/0x5a0 [zfs]
Apr 22 19:10:03 wopr kernel: dmu_object_free+0x53/0x90 [zfs]
Apr 22 19:10:03 wopr kernel: dmu_free_long_object+0x9f/0xc0 [zfs]
Apr 22 19:10:03 wopr kernel: receive_freeobjects.isra.12+0x7a/0x100 [zfs]
Apr 22 19:10:03 wopr kernel: receive_writer_thread+0x6d2/0xa60 [zfs]
Apr 22 19:10:03 wopr kernel: ? set_curr_task_fair+0x2b/0x60
Apr 22 19:10:03 wopr kernel: ? spl_kmem_free+0x33/0x40 [spl]
Apr 22 19:10:03 wopr kernel: ? kfree+0x165/0x180
Apr 22 19:10:03 wopr kernel: ? receive_free.isra.13+0xc0/0xc0 [zfs]
Apr 22 19:10:03 wopr kernel: thread_generic_wrapper+0x74/0x90 [spl]
Apr 22 19:10:03 wopr kernel: kthread+0x121/0x140
Apr 22 19:10:03 wopr kernel: ? __thread_exit+0x20/0x20 [spl]
Apr 22 19:10:03 wopr kernel: ? kthread_create_worker_on_cpu+0x70/0x70
Apr 22 19:10:03 wopr kernel: ret_from_fork+0x35/0x40
Apr 22 19:12:56 wopr kernel: INFO: task txg_quiesce:2265 blocked for more than 120 seconds.
Apr 22 19:12:56 wopr kernel: Tainted: P O 4.15.0-91-generic #92-Ubuntu
Apr 22 19:12:56 wopr kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 22 19:12:56 wopr kernel: txg_quiesce D 0 2265 2 0x80000000
Apr 22 19:12:56 wopr kernel: Call Trace:
Apr 22 19:12:56 wopr kernel: __schedule+0x24e/0x880
Apr 22 19:12:56 wopr kernel: schedule+0x2c/0x80
Apr 22 19:12:56 wopr kernel: cv_wait_common+0x11e/0x140 [spl]
Apr 22 19:12:56 wopr kernel: ? wait_woken+0x80/0x80
Apr 22 19:12:56 w...

i've uploaded a debug zfs-dkms package to https://launchpad.net/~colin-king/+archive/ubuntu/zfs-sru-1861235 for testing. This will dump out internal state of the driver to get a better idea of what is happening during this crash.

Please can you test this by doing the following:

sudo add-apt-repository ppa:colin-king/zfs-sru-1861235
sudo apt-get update
sudo apt-get install zfs-dkms

let this debug dkms zfs module build and reboot. when the failure occurs again please supply as much of the dmesg output as possible

Thank you

Here's the part that looks important; the whole dmesg is in the attachment.

Thanks

[ 761.730488] dnone_free_ramge: nblks = 0, trunc = 1, len = 18446744073709551615, blkshift = 0
[ 761.730542] dnode_free_range: nblks == 0, len == 18446744073709551615
               , off=0
[ 761.730543] range_tree_clear: size == 0
[ 761.730605] VERIFY(size != 0) failed
[ 761.730625] PANIC at range_tree.c:307:range_tree_find_impl()
[ 761.730653] Showing stack for process 23913
[ 761.730656] CPU: 31 PID: 23913 Comm: receive_writer Tainted: P OE 4.15.0-99-generic #100-Ubuntu
[ 761.730657] Hardware name: Supermicro SSG-6038R-E1CR16L/X10DRH-iT, BIOS 2.0 12/17/2015
[ 761.730658] Call Trace:
[ 761.730668] dump_stack+0x6d/0x8e
[ 761.730679] spl_dumpstack+0x42/0x50 [spl]
[ 761.730684] spl_panic+0xc8/0x110 [spl]
[ 761.730690] ? fbcon_cursor+0x13e/0x1c0
[ 761.730695] ? atomic_notifier_call_chain+0x1a/0x20
[ 761.730700] ? vt_console_print+0x240/0x410
[ 761.730705] ? up+0x32/0x50
[ 761.730708] ? console_unlock+0x2a1/0x560
[ 761.730767] range_tree_find_impl+0x88/0x90 [zfs]
[ 761.730769] ? printk+0x52/0x6e
[ 761.730810] range_tree_clear+0x54/0x70 [zfs]
[ 761.730843] dnode_free_range+0x15b/0x720 [zfs]
[ 761.730874] dmu_object_free+0x75/0xc0 [zfs]
[ 761.730904] dmu_free_long_object+0x9f/0xc0 [zfs]
[ 761.730934] receive_freeobjects.isra.12+0x7a/0x100 [zfs]
[ 761.730963] receive_writer_thread+0x6d2/0xa60 [zfs]
[ 761.730965] ? set_curr_task_fair+0x2b/0x60
[ 761.730970] ? spl_kmem_free+0x33/0x40 [spl]
[ 761.730973] ? kfree+0x162/0x180
[ 761.731001] ? receive_free.isra.13+0xc0/0xc0 [zfs]
[ 761.731006] thread_generic_wrapper+0x74/0x90 [spl]
[ 761.731008] kthread+0x121/0x140
[ 761.731012] ? __thread_exit+0x20/0x20 [spl]
[ 761.731014] ? kthread_create_worker_on_cpu+0x70/0x70
[ 761.731018] ret_from_fork+0x35/0x40
[ 967.430681] INFO: task txg_quiesce:4049 blocked for more than 120 seconds.
[ 967.430739] Tainted: P OE 4.15.0-99-generic #100-Ubuntu
[ 967.430785] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 967.430836] txg_quiesce D 0 4049 2 0x80000000
[ 967.430840] Call Trace:
[ 967.430853] __schedule+0x24e/0x880
[ 967.430858] schedule+0x2c/0x80
[ 967.430875] cv_wait_common+0x11e/0x140 [spl]
[ 967.430885] ? wait_woken+0x80/0x80
[ 967.430893] __cv_wait+0x15/0x20 [spl]
[ 967.431010] txg_quiesce_thread+0x2cb/0x3d0 [zfs]
[ 967.431078] ? txg_delay+0x1b0/0x1b0 [zfs]
[ 967.431088] thread_generic_wrapper+0x74/0x90 [spl]
[ 967.431093] kthread+0x121/0x140
[ 967.431099] ? __thread_exit+0x20/0x20 [spl]
[ 967.431102] ? kthread_create_worker_on_cpu+0x70/0x70
[ 967.431107] ret_from_fork+0x35/0x40
[ 967.431140] INFO: task zfs:23834 blocked for more than 120 seconds.
[ 967.431184] Tainted: P OE 4.15.0-99-generic #100-Ubuntu
[ 967.431229] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 967.431279] zfs D 0 23834 23831 0x80000080
[ 967.431282] Call Trace:
[ 967.431286] __schedule+0x24e/0x880
[ 967.431290] schedule+0x2c/0x80
[ 967.431298] cv_wait_common+0x11e/0x140 [spl]
[ ...

Thanks for the data.

I've added a couple more lines of debug now to figure out some earlier missing information once we pop the stack. I've updated the package in the PPA, do you mind updating the zfs-dkms to 0.7.5-1ubuntu16.10~lp1861235.2 and re-testing?

Thanks Colin!

[ 271.628232] dnone_free_ramge: nblks = 0, trunc = 1, len = 18446744073709551615, blkshift = 0
[ 271.628297] dnode_free_range: nblks == 0, len == 18446744073709551615
               , off=0
[ 271.628298] range_tree_clear: size == 0
[ 271.628375] range_tree_find_impl: size == 0
[ 271.628393] VERIFY(size != 0) failed
[ 271.628409] PANIC at range_tree.c:168:range_tree_add()
[ 271.628429] Showing stack for process 7960
[ 271.628432] CPU: 26 PID: 7960 Comm: receive_writer Tainted: P OE 4.15.0-99-generic #100-Ubuntu
[ 271.628433] Hardware name: Supermicro SSG-6038R-E1CR16L/X10DRH-iT, BIOS 2.0 12/17/2015
[ 271.628433] Call Trace:
[ 271.628442] dump_stack+0x6d/0x8e
[ 271.628458] spl_dumpstack+0x42/0x50 [spl]
[ 271.628462] spl_panic+0xc8/0x110 [spl]
[ 271.628468] ? vt_console_print+0x240/0x410
[ 271.628473] ? console_unlock+0x2a1/0x560
[ 271.628475] ? vprintk_emit+0x104/0x2c0
[ 271.628477] ? vprintk_default+0x29/0x50
[ 271.628479] ? printk+0x52/0x6e
[ 271.628566] range_tree_add+0x29b/0x300 [zfs]
[ 271.628600] ? range_tree_clear+0xa4/0xb0 [zfs]
[ 271.628602] ? printk+0x52/0x6e
[ 271.628635] dnode_free_range+0x178/0x720 [zfs]
[ 271.628673] dmu_object_free+0x6d/0xc0 [zfs]
[ 271.628698] dmu_free_long_object+0x9f/0xc0 [zfs]
[ 271.628723] receive_freeobjects.isra.12+0x7a/0x100 [zfs]
[ 271.628747] receive_writer_thread+0x6d2/0xa60 [zfs]
[ 271.628750] ? set_curr_task_fair+0x2b/0x60
[ 271.628753] ? spl_kmem_free+0x33/0x40 [spl]
[ 271.628757] ? kfree+0x162/0x180
[ 271.628781] ? receive_free.isra.13+0xc0/0xc0 [zfs]
[ 271.628785] thread_generic_wrapper+0x74/0x90 [spl]
[ 271.628788] kthread+0x121/0x140
[ 271.628791] ? __thread_exit+0x20/0x20 [spl]
[ 271.628792] ? kthread_create_worker_on_cpu+0x70/0x70
[ 271.628796] ret_from_fork+0x35/0x40

Hi, I was expecting some extra information and a panic message in a different place, are you sure this is running the latest zfs-dkms? One can check that by using dmesg | grep ZFS and check this is the .2 version of the debug zfd-dkms package.

Oh, I see you are using the latest version: v0.7.5-1ubuntu16.10~lp1861235.2

I may need to figure out a .3 version to try next.

Thanks for the data for the .2 tests. I've updated the packages with a .3 test build.

I've added a couple more lines of debug now to figure out some earlier missing information once we pop the stack. I've updated the package in the PPA, do you mind updating the zfs-dkms to 0.7.5-1ubuntu16.10~lp1861235.3 and re-testing?

Hello Colin, trying the zfs recv operation on the .3 dkms eventually kills my system dead. There was nothing on the console. The cursor on the console stopped blinking; I couldn't switch VTs. My ssh sessions were hung. ping reported destination host unreachable.

It ran for about two and a half minutes, transferred around 10 datasets or snapshots:
$ journalctl -b -1 | grep -c "COMMAND=/sbin/zfs receive"
10

Sadly, journalctl doesn't have the dmesg from the previous boot:

$ journalctl -b -1 -k
[...]
May 15 17:25:10 wopr kernel: ZFS: Loaded module v0.7.5-1ubuntu16.10~lp1861235.3, ZFS pool version 5000, ZFS filesystem version 5
May 15 17:25:15 wopr kernel: zd32: p1
May 15 17:25:20 wopr kernel: pps pps0: new PPS source ptp0
May 15 17:25:20 wopr kernel: ixgbe 0000:05:00.0: registered PHC device on enp5s0f0
May 15 17:25:20 wopr kernel: IPv6: ADDRCONF(NETDEV_UP): enp5s0f0: link is not ready
May 15 17:25:20 wopr kernel: new mount options do not match the existing superblock, will be ignored
May 15 17:25:21 wopr kernel: Process accounting resumed
May 15 17:25:24 wopr kernel: ixgbe 0000:05:00.0 enp5s0f0: NIC Link is Up 1 Gbps, Flow Control: None
May 15 17:25:24 wopr kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp5s0f0: link becomes ready
May 15 17:25:29 wopr kernel: NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
May 15 17:25:29 wopr kernel: NFSD: starting 90-second grace period (net f00000a9)
May 15 17:25:32 wopr kernel: ip6_tables: (C) 2000-2006 Netfilter Core Team
May 15 17:25:32 wopr kernel: Ebtables v2.0 registered
May 15 17:25:33 wopr kernel: bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
May 15 17:25:33 wopr kernel: virbr0: port 1(virbr0-nic) entered blocking state
May 15 17:25:33 wopr kernel: virbr0: port 1(virbr0-nic) entered disabled state
May 15 17:25:33 wopr kernel: device virbr0-nic entered promiscuous mode
May 15 17:25:33 wopr kernel: nf_conntrack version 0.5.0 (65536 buckets, 262144 max)
May 15 17:25:33 wopr kernel: virbr0: port 1(virbr0-nic) entered blocking state
May 15 17:25:33 wopr kernel: virbr0: port 1(virbr0-nic) entered listening state
May 15 17:25:33 wopr kernel: virbr0: port 1(virbr0-nic) entered disabled state

Thanks

On Sat, May 16, 2020 at 01:56:08AM -0000, Seth Arnold wrote:
> Sadly, journalctl doesn't have the dmesg from the previous boot:

I meant to say, journalctl's copy of dmesg from the previous boot doesn't
have the new debug output. Sorry.

Thanks

Hi Seth, I've upload a .4 - it may add a lot more debug but it will allow us to see the object type that is failing before the crash.

Colin, you're not kidding, there's a lot more debug information in this one. Here's the part that looks important:

[ 289.167264] dmu_object_free: object = 0x8319, dn->dn_type = 196
[ 289.167659] dmu_object_free: object = 0x8318, dn->dn_type = 13
[ 289.167922] dmu_object_free: object = 0x8317, dn->dn_type = 15
[ 289.168197] dmu_object_free: object = 0x8316, dn->dn_type = 12
[ 289.168500] dmu_object_free: object = 0x861b, dn->dn_type = 195
[ 289.351934] dmu_object_free: object = 0x5ef6, dn->dn_type = 50
[ 289.353287] dmu_object_free: object = 0x8553, dn->dn_type = 37
[ 289.353704] dmu_object_free: object = 0x65bb, dn->dn_type = 196
[ 289.917945] dmu_object_free: object = 0x210, dn->dn_type = 19
[ 289.918616] dmu_object_free: object = 0x211, dn->dn_type = 32
[ 289.919025] dnone_free_ramge: nblks = 0, trunc = 1, len = 0xffffffffffffffff, blkshift = 0
[ 289.919442] dnode_free_range: nblks == 0, len == 18446744073709551615
               , off=0
[ 289.919443] range_tree_clear: size == 0
[ 289.920690] range_tree_find_impl: size == 0
[ 289.921123] VERIFY(size != 0) failed
[ 289.921566] PANIC at range_tree.c:319:range_tree_find_impl()
[ 289.922043] Showing stack for process 28938
[ 289.922047] CPU: 15 PID: 28938 Comm: receive_writer Tainted: P OE 4.15.0-101-generic #102-Ubuntu
[ 289.922049] Hardware name: Supermicro SSG-6038R-E1CR16L/X10DRH-iT, BIOS 2.0 12/17/2015
[ 289.922050] Call Trace:
[ 289.922064] dump_stack+0x6d/0x8e
[ 289.922082] spl_dumpstack+0x42/0x50 [spl]
[ 289.922089] spl_panic+0xc8/0x110 [spl]
[ 289.922098] ? console_unlock+0x2a1/0x560
[ 289.922102] ? vprintk_emit+0x104/0x2c0
[ 289.922106] ? vprintk_default+0x29/0x50
[ 289.922111] ? vprintk_func+0x47/0xc0
[ 289.922114] ? printk+0x52/0x6e
[ 289.922201] range_tree_find_impl+0x94/0xa0 [zfs]
[ 289.922205] ? printk+0x52/0x6e
[ 289.922268] range_tree_clear+0x54/0x70 [zfs]
[ 289.922322] dnode_free_range+0x15b/0x720 [zfs]
[ 289.922372] dmu_object_free+0x80/0xd0 [zfs]
[ 289.922420] dmu_free_long_object+0x9f/0xc0 [zfs]
[ 289.922469] receive_freeobjects.isra.12+0x7a/0x100 [zfs]
[ 289.922517] receive_writer_thread+0x6d2/0xa60 [zfs]
[ 289.922521] ? set_curr_task_fair+0x2b/0x60
[ 289.922528] ? spl_kmem_free+0x33/0x40 [spl]
[ 289.922535] ? kfree+0x168/0x180
[ 289.922581] ? receive_free.isra.13+0xc0/0xc0 [zfs]
[ 289.922589] thread_generic_wrapper+0x74/0x90 [spl]
[ 289.922594] kthread+0x121/0x140
[ 289.922600] ? __thread_exit+0x20/0x20 [spl]
[ 289.922603] ? kthread_create_worker_on_cpu+0x70/0x70
[ 289.922610] ret_from_fork+0x35/0x40
[ 484.358156] INFO: task txg_quiesce:3136 blocked for more than 120 seconds.
[ 484.358778] Tainted: P OE 4.15.0-101-generic #102-Ubuntu
[ 484.359320] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 484.359898] txg_quiesce D 0 3136 2 0x80000000
[ 484.359902] Call Trace:
[ 484.359914] __schedule+0x24e/0x880
[ 484.359918] schedule+0x2c/0x80
[ 484.359935] cv_wait_common+0x11e/0x140 [spl]
[ 484.359942] ? wait_woken+0x80/0x80
[ 484.359951] __cv_wait+0x15/0x20 [spl]
[ 484.360056] txg_quiesce_thread+0x2cb/0x3d0 [zfs]
[ 484.3...

OK so object 0x211 looks like the curlprit, I just can't see the pool name being dumped - do you know which pool is triggering this issue?

If you can identify the poolt then we can next dump the potentially corrupt object using:

sudo zdb -dddd <pool>/<dataset> 529

I picked the last dataset given in the command output from an earlier, but not the most recent, comment:

$ sudo zdb -dddd srv/backups/millbarge/rpool/var/log 529
Dataset srv/backups/millbarge/rpool/var/log [ZPL], ID 39694, cr_txg 23197757, 554M, 274 objects, rootbp DVA[0]=<1:1d000d42000:1000> DVA[1]=<2:24416f4b000:1000> [L0 DMU objset] sha256 uncompressed LE contiguous unique double size=800L/800P birth=23437543L/23437543P fill=274 cksum=cf5fcb2f986c768c:7cc8638aeb1a5162:9de9f236f072e16:40c6a08d90b54951

    Object lvl iblk dblk dsize dnsize lsize %full type
       529 0 0 0 0 512 0 -nan DSL permissions (K=UNKNOWN) (Z=UNKNOWN)
                                                 0 bonus UNKNOWN
 dnode flags: USED_BYTES USERUSED_ACCOUNTED USEROBJUSED_ACCOUNTED SPILL_BLKPTR
 dnode maxblkid: 0
 UNKNOWN OBJECT TYPE
c < (1ULL << 24) >> 9 (0x7fffffffffffff < 0x8000)
ASSERT at ../../module/zfs/zio.c:266:zio_buf_alloc()Aborted

Thanks

Is it interesting that I'm seeing both 19 and 20 in my dmesg?

[1229822.406130] dmu_object_free: object = 0x266d2904, dn->dn_type = 20
[1229823.980888] dmu_object_free: object = 0x266d0d5a, dn->dn_type = 20
[1229823.994690] dmu_object_free: object = 0x266d0d5b, dn->dn_type = 20
[1229823.998123] dmu_object_free: object = 0x266d00c1, dn->dn_type = 19
[1229823.998191] dmu_object_free: object = 0x266d00c3, dn->dn_type = 19
[1229823.998324] dmu_object_free: object = 0x266d00c5, dn->dn_type = 19
[1229823.998377] dmu_object_free: object = 0x266d00c4, dn->dn_type = 20

Thanks

Hi @seth-arnold,

adding some details to this bug:

 dn->dn_type = 19 = DMU_OT_PLAIN_FILE_CONTENTS
 dn->dn_type = 20 = DMU_OT_DIRECTORY_CONTENTS

So they look correct, they seem to be just plain files and directories.

However, the specific object that is causing the panic seems to have dn_type=32 that is DMU_OT_DSL_PERMS (that's a bit odd, I don't see any other object types like this in your dmesg), moreover the output of "zdb -dddd" shows a lot of UNKNONW stuff (checksum and compression type for example, they are UNKNOWN).

So, it seems that we may have some corrupted data here.

Do you see any error if you try to run a simple `zpool status -v`? Do you know exactly which pool / volume / filesystem is causing this problem?

I just noticed the bug on github that also mentions about potential data corruption. It looks like we need to recompile zfs with --enable-debug. I'll try to produce a debug package with that.

I've uploaded the latest version of zfs with debugging enabled (--enable-debug) in this ppa:
https://launchpad.net/~arighi/+archive/ubuntu/zfs-linux

sudo add-apt-repository ppa:arighi/zfs-linux
sudo apt-get update
sudo apt-get install zfs-dkms

It'd be interesting to repeat the test using this version. Make sure the loaded zfs module is matching the right version:

$ modinfo zfs | grep ^version
version: 0.7.5-1ubuntu16.10+lp1861235

Moreover, if the data got corrupted, it'd be interesting to know why... can you provide some smartctl information? Did you notice any I/O error in your logs? Thanks!

Hello Andrea, thanks for looking into my problem.

# zpool status -v
  pool: fst
 state: ONLINE
  scan: scrub repaired 0B in 2h37m with 0 errors on Sun Nov 8 03:01:53 2020
config:

 NAME STATE READ WRITE CKSUM
 fst ONLINE 0 0 0
   raidz1-0 ONLINE 0 0 0
     wwn-0x5002538e4095da39 ONLINE 0 0 0
     wwn-0x5002538e4095bdd6 ONLINE 0 0 0
     wwn-0x5002538e4093c6fd ONLINE 0 0 0
     wwn-0x5002538e4095da30 ONLINE 0 0 0

errors: No known data errors

  pool: srv
 state: ONLINE
  scan: scrub repaired 0B in 3h44m with 0 errors on Sun Nov 8 04:08:16 2020
config:

 NAME STATE READ WRITE CKSUM
 srv ONLINE 0 0 0
   mirror-0 ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P8KTWJYY ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G620TW ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G66E2U ONLINE 0 0 0
   mirror-1 ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G69TKU ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G69TXU ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G69U2U ONLINE 0 0 0
   mirror-2 ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G6EBUU ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G6ESAU ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G6G70U ONLINE 0 0 0
 logs
   nvme0n1p1 ONLINE 0 0 0
 cache
   nvme0n1p2 ONLINE 0 0 0

errors: No known data errors

I'll swap over to your dkms build and report back.

Thanks

Picking the previous bad object (which I'm pretty sure should still be intact):

$ modinfo zfs | grep ^version
version: 0.7.5-1ubuntu16.10+lp1861235
$ uname -a
Linux wopr 4.15.0-126-generic #129-Ubuntu SMP Mon Nov 23 18:53:38 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
$ sudo zdb -dddd srv/backups/millbarge/rpool/var/log 529
Dataset srv/backups/millbarge/rpool/var/log [ZPL], ID 39694, cr_txg 23197757, 554M, 274 objects, rootbp DVA[0]=<1:1d000d42000:1000> DVA[1]=<2:24416f4b000:1000> [L0 DMU objset] sha256 uncompressed LE contiguous unique double size=800L/800P birth=23437543L/23437543P fill=274 cksum=cf5fcb2f986c768c:7cc8638aeb1a5162:9de9f236f072e16:40c6a08d90b54951

    Object lvl iblk dblk dsize dnsize lsize %full type
dn->dn_nblkptr >= 1 (0x0 >= 0x1)
ASSERT at ../../module/zfs/dnode.c:278:dnode_verify()Aborted
$ dmesg | tail
[ 43.017302] Ebtables v2.0 registered
[ 44.977437] L1TF CPU bug present and SMT on, data leak possible. See CVE-2018-3646 and https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/l1tf.html for details.
[ 47.047114] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[ 47.047966] virbr0: port 1(virbr0-nic) entered blocking state
[ 47.047968] virbr0: port 1(virbr0-nic) entered disabled state
[ 47.048063] device virbr0-nic entered promiscuous mode
[ 47.433533] nf_conntrack version 0.5.0 (65536 buckets, 262144 max)
[ 47.971009] virbr0: port 1(virbr0-nic) entered blocking state
[ 47.971013] virbr0: port 1(virbr0-nic) entered listening state
[ 48.321853] virbr0: port 1(virbr0-nic) entered disabled state
$

Here's smartctl output on the disks in the pool. It's a bit hard to summarize nine drives of smartctl output but nothing stood out as interesting to me.

My journals only go back a few months so they wouldn't show any IO errors at the time of this problem being introduced, but this currently gives no results:

journalctl | grep -i "i/o error"

so there's nothing recent.

I started a new scrub, it'll finish in a few hours, if I forget to post results please do remind me. :)

Thanks

The scrub has finished, no new errors in zpool status -v, dmesg is filled with debugging messages, I hope something is useful. :)

Thanks

$ uname -a
Linux wopr 4.15.0-126-generic #129-Ubuntu SMP Mon Nov 23 18:53:38 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
$ modinfo zfs | grep -i version
version: 0.7.5-1ubuntu16.10+lp1861235
srcversion: 62D1F1B1A1EE81EB3AA8ABA
$ zpool status -v
  pool: fst
 state: ONLINE
  scan: scrub repaired 0B in 2h37m with 0 errors on Sun Nov 8 03:01:53 2020
config:

 NAME STATE READ WRITE CKSUM
 fst ONLINE 0 0 0
   raidz1-0 ONLINE 0 0 0
     wwn-0x5002538e4095da39 ONLINE 0 0 0
     wwn-0x5002538e4095bdd6 ONLINE 0 0 0
     wwn-0x5002538e4093c6fd ONLINE 0 0 0
     wwn-0x5002538e4095da30 ONLINE 0 0 0

errors: No known data errors

  pool: srv
 state: ONLINE
  scan: scrub repaired 0B in 4h12m with 0 errors on Wed Dec 2 18:53:44 2020
config:

 NAME STATE READ WRITE CKSUM
 srv ONLINE 0 0 0
   mirror-0 ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P8KTWJYY ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G620TW ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G66E2U ONLINE 0 0 0
   mirror-1 ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G69TKU ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G69TXU ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G69U2U ONLINE 0 0 0
   mirror-2 ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G6EBUU ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G6ESAU ONLINE 0 0 0
     ata-HGST_HUS724030ALA640_PN2234P9G6G70U ONLINE 0 0 0
 logs
   nvme0n1p1 ONLINE 0 0 0
 cache
   nvme0n1p2 ONLINE 0 0 0

errors: No known data errors

My guess is the next step is trying the zfs send | ssh zfs recv commands that were causing the VERIFY(size != 0) failed message with traces. I've always been uneasy with the 'main' error coming only with a recv operation, relying upon two systems to recreate a bug is iffy at best. And since it wedges the one, I don't like doing it just for fun, but I'd also like to get to the bottom of this.

Is there anything else to try first?

Thanks

This time I don't see any error or panic in `journalctl -b` and apparently everything is fine according to smartctl, so it looks like we are not getting any obvious I/O error at the moment.

IIUC you have done already a `zpool scrub` and that also didn't report any error, so apparently the zfs data integrigy checks passed locally.

If that's the case, yes, I think the next step would be to try to `zfs send | zfs recv` commands and see if we get more information with zfs debugging enabled. Alternatively we could try to stress the local zpool more, maybe running some I/O stress test (fio for example) on some volumes / filesystems created from the "potentially faulty" zpool. Apart than that I don't see any other useful test that we can do...

Status changed to 'Confirmed' because the bug affects multiple users.