Crash with ZFS recv from TrueNAS CORE to SCALE at over 1TB

[Sean Hafeez]

I have opened a Jira:
NAS-113624

Posting here wondering if anyone else has seen this or if anyone has been able to make this work in a similar setup.

Local system is Mini-2.0 running TrueNAS-12.0-U6.1
Remote is Mini-3.0-XL+ running TrueNAS-SCALE-22.02-RC.1-2
Sending a snapshot under 1T works fine. Sending the one that is 1.91T breaks at 1.01T

Remote:
mbuffer -I 9090 | zfs receive data/barrel-old/music@migrate
Local:
zfs snapshot main/music@migrate
zfs send -v main/music@migrate | mbuffer -O barrel2:9090

On Local I see this 1000 times when it hangs:
in @ 0.0 kiB/s, out @ 0.0 kiB/s, 1031 GiB total, buffer 100% full07:45:36 1.01T main/music@migrate
I am able to ctrl-c the process

On the Remote I see this on the console:
VERIFY3(drrw->drr_logical_size > dn->dn_datablksz) failed (118784 > 131072)
This zfs receive is NOT KILLABLE - it ignores kill -9 etc. I have to issue reboot from ssh and that hangs for 3-4 minutes before it reboots.

Manually setting mbuffer memory sizes does not change what happens.

Here is the crash:

[10099.095091] VERIFY3(drrw->drr_logical_size > dn->dn_datablksz) failed (118784 > 131072)
[10099.095155] PANIC at dmu_recv.c:1906:flush_write_batch_impl()
[10099.095190] Showing stack for process 56507
[10099.095218] CPU: 6 PID: 56507 Comm: receive_writer Tainted: P OE 5.10.70+truenas #1
[10099.095270] Hardware name: iXsystems TRUENAS-MINI-3.0-XL+/A2SDi-H-TF, BIOS 1.3.V1 06/08/2020
[10099.095318] Call Trace:
[10099.095345] dump_stack+0x6b/0x83
[10099.095380] spl_panic+0xd4/0xfc [spl]
[10099.095520] ? list_head+0x9/0x20 [zfs]
[10099.095662] ? txg_list_add+0x99/0xd0 [zfs]
[10099.095791] ? dsl_dir_dirty+0x34/0x80 [zfs]
[10099.095918] ? dsl_dir_willuse_space+0xab/0x110 [zfs]
[10099.095951] ? _cond_resched+0x16/0x40
[10099.096077] ? dsl_pool_dirty_space+0x83/0xc0 [zfs]
[10099.096201] ? flush_write_batch_impl+0x23c/0x550 [zfs]
[10099.096326] flush_write_batch_impl+0x452/0x550 [zfs]
[10099.096449] ? dmu_free_long_range_impl+0x38/0x460 [zfs]
[10099.096580] flush_write_batch+0x37/0xb0 [zfs]
[10099.096700] receive_process_record+0x87/0x2b0 [zfs]
[10099.096824] receive_writer_thread+0xb3/0x1c0 [zfs]
[10099.096948] ? receive_process_record+0x2b0/0x2b0 [zfs]
[10099.096989] thread_generic_wrapper+0x78/0xb0 [spl]
[10099.097028] ? IS_ERR+0x10/0x10 [spl]
[10099.097053] kthread+0x11b/0x140
[10099.098145] ? __kthread_bind_mask+0x60/0x60
[10099.099240] ret_from_fork+0x22/0x30
[10271.696313] INFO: task txg_quiesce:11778 blocked for more than 120 seconds.
[10271.699427] Tainted: P OE 5.10.70+truenas #1
[10271.702631] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10271.705920] task:txg_quiesce state:D stack: 0 pid:11778 ppid: 2 flags:0x00004000
[10271.709285] Call Trace:
[10271.712633] __schedule+0x282/0x870
[10271.715970] schedule+0x46/0xb0
[10271.719357] cv_wait_common+0x14e/0x290 [spl]
[10271.722755] ? add_wait_queue_exclusive+0x70/0x70
[10271.726517] txg_quiesce+0x1d1/0x2d0 [zfs]
[10271.730317] txg_quiesce_thread+0xe6/0x230 [zfs]
[10271.734118] ? txg_quiesce+0x2d0/0x2d0 [zfs]
[10271.737629] thread_generic_wrapper+0x78/0xb0 [spl]
[10271.741140] ? IS_ERR+0x10/0x10 [spl]
[10271.744666] kthread+0x11b/0x140
[10271.747733] ? __kthread_bind_mask+0x60/0x60
[10271.750849] ret_from_fork+0x22/0x30
[10271.754016] INFO: task receive_writer:56507 blocked for more than 120 seconds.
[10271.757251] Tainted: P OE 5.10.70+truenas #1
[10271.759925] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10271.762652] task:receive_writer state:D stack: 0 pid:56507 ppid: 2 flags:0x00004000

 

[morganL]

If its replicable as you describe, please "report a bug".

 

[Sean Hafeez]

At the top I state:

I have opened a Jira:
NAS-113624

I have also added the same to the OpenZFS bug on Github.

Send-Recv: `VERIFY3(drrw->drr_logical_size > dn->dn_datablksz) failed (75264 > 131072)` · Issue #12778 · openzfs/zfs

Short memo: System: Latest TrueNAS SCALE build During the folloing command: zfs send old/library/music@migrate | zfs recv -x encryption tank/library/music the following errors get dumped: VERIFY3(d...

github.com

 

[dalnew]

Interesting... I am seeing something *very* similar when trying to replicate one pool to another on the same TrueNAS Scale machine. I basically have two pools a 42TB RAIDZ1 pool 'zeus' and a 65TB RAIDZ2 pool 'hera'. I want to repurpose the 4 drives composing zeus into a new backup machine but first I need to replicate the entire zeus pool into hera. To do that I first made a zeus snapshot:

sudo zfs snap -r zeus@golden_moving_12.7.21

And then I tried to send the data over to the new pool.

sudo zfs send -R zeus@golden_moving_12.7.21 | sudo zfs recv -Fvs hera

However it's immediately apparent that nothing is working as there's no zfs activity on top and the processes look like:

4 0 48488 28520 20 0 9276 4348 - S+ pts/3 0:00 sudo zfs send -R zeus@golden_moving_12.7.21
4 0 48489 28520 20 0 9276 4368 - S+ pts/3 0:00 sudo zfs recv -Fvs hera
4 0 48490 48489 20 0 10752 5080 - S+ pts/3 0:00 zfs recv -Fvs hera
4 0 48491 48488 20 0 11240 5368 - S+ pts/3 0:00 zfs send -R zeus@golden_moving_12.7.21

I'm not sure why there are 4 of them, given I only executed one command.

Also if I look at /var/log/messages and dmesg I see a bunch of similar crashes like yours (attached logs) and no way of killing the entire receive process short of completely rebooting. This is 100% reproducible everytime I try to do a zfs send/receive.

One question, the pools i'm trying to replicate are using a slightly older version of ZFS ( meaning I get the stereotypical warning below. I still haven't upgraded them out of an abundance of caution. It shouldn't matter that my new pool is newer right?

WARNING
New ZFS version or feature flags are available for pool zeus. Upgrading pools is a one-time process that can prevent rolling the system back to an earlier TrueNAS version. It is recommended to read the TrueNAS release notes and confirm you need the new ZFS feature flags before upgrading a pool.

Should I add this info to the above ticket or file a new bug report? I guess this is already being tracked by https://github.com/openzfs/zfs/issues/12778

I guess it's just unclear if it's a ZFS linux only issue, TrueNAS, or something else.

 

[freqlabs]

This crash does not affect release versions of TrueNAS, the ASSERT in question is only checked in debug builds of ZFS.

 

[gary_1]

I'm seeing a similar issue (different line in dmu_recv) on version "TrueNAS-SCALE-22.02.1" which I installed a couple of days ago. I first noticed attempting to run my normal pool replication task to a single disk usb pool.

I figured maybe Scale is just more picky than Core was about USB, so after a reboot I tried to do a replication to my second backup server (also running scale). In this case, I experienced the assert on the backup server.

I'm not sure if this is just a coincidence, but in both cases it crashed trying to replicate the same snapshot. That snapshot appears to be amongst the first batch of dataset snapshots created post migration from core to scale. The snapshots that replicated fine before the crash/assert were taken whilst running under core.

Edit: As an extra datapoint, snapshots are being replicated to a encrypted target pool that has not been unlocked. Previously doing Core -> Scale replication over the last few months has worked without issue, however, now trying Scale -> Scale (and also Scale -> local usb pool) asserts.

Edit2: This is the exact error logged on the backup server (also running TrueNAS-SCALE-22.02.1) when replicating the offending snapshot, which is 1.44MB

2022 Jun 12 00:32:59 babylon2 VERIFY3(0 == dmu_object_set_blocksize(rwa->os, drro->drr_object, drro->drr_blksz, drro->drr_indblkshift, tx)) failed (0 == 95)
2022 Jun 12 00:32:59 babylon2 PANIC at dmu_recv.c:1776:receive_object()
Jun 12 00:32:59 babylon2 kernel: Showing stack for process 8597
Jun 12 00:32:59 babylon2 kernel: CPU: 4 PID: 8597 Comm: receive_writer Tainted: P OE 5.10.109+truenas #1
Jun 12 00:32:59 babylon2 kernel: Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./B450M Pro4, BIOS P3.50 07/18/2019
Jun 12 00:32:59 babylon2 kernel: Call Trace:
Jun 12 00:32:59 babylon2 kernel: dump_stack+0x6b/0x83
Jun 12 00:32:59 babylon2 kernel: spl_panic+0xd4/0xfc [spl]
Jun 12 00:32:59 babylon2 kernel: ? arc_buf_access+0x14c/0x250 [zfs]
Jun 12 00:32:59 babylon2 kernel: ? dnode_hold_impl+0x4e9/0xef0 [zfs]
Jun 12 00:32:59 babylon2 kernel: ? dnode_set_blksz+0x13b/0x300 [zfs]
Jun 12 00:32:59 babylon2 kernel: ? dnode_rele_and_unlock+0x5c/0xc0 [zfs]
Jun 12 00:32:59 babylon2 kernel: receive_object+0xc2c/0xca0 [zfs]
Jun 12 00:32:59 babylon2 kernel: ? dnode_rele_and_unlock+0x5c/0xc0 [zfs]
Jun 12 00:32:59 babylon2 kernel: ? flush_write_batch+0x1de/0x560 [zfs]
Jun 12 00:32:59 babylon2 kernel: receive_writer_thread+0x1cc/0xad0 [zfs]
Jun 12 00:32:59 babylon2 kernel: ? thread_generic_wrapper+0x62/0x80 [spl]
Jun 12 00:32:59 babylon2 kernel: ? kfree+0x40c/0x480
Jun 12 00:32:59 babylon2 kernel: ? receive_process_write_record+0x190/0x190 [zfs]
Jun 12 00:32:59 babylon2 kernel: ? thread_generic_wrapper+0x6f/0x80 [spl]
Jun 12 00:32:59 babylon2 kernel: thread_generic_wrapper+0x6f/0x80 [spl]
Jun 12 00:32:59 babylon2 kernel: ? __thread_exit+0x20/0x20 [spl]
Jun 12 00:32:59 babylon2 kernel: kthread+0x11b/0x140
Jun 12 00:32:59 babylon2 kernel: ? __kthread_bind_mask+0x60/0x60
Jun 12 00:32:59 babylon2 kernel: ret_from_fork+0x22/0x30

 

[gary_1]

I'm not sure what the cause was, but I deleted all the snapshots in the dataset this morning and removed the dataset from the backup server then started the replication again. This time it completed including successful replication of the other datasets snapshots.

Hopefully the same workaround will work for the local disk replication too.

 

[freqlabs]

@gary_1 your error is different from the others in the thread. If you run into this again you may report a TrueNAS bug using the link at the top of the page so we can get more debug info from the system.