Latest stable syncoid fails on initial send/receive: cannot receive incremental stream: dataset is busy

marceldegraaf commented 3 years ago

TL;DR – latest stable syncoid fails on Debian 10 when performing the initial send/receive from a non-encrypted to an encrypted pool. The error seems to be cannot receive incremental stream: dataset is busy. Issue #598 seems similar, although in that case a sendoption flag seems to have been the culprit. I'm not using those in my syncoid command, and AFAIK my ZFS setup is pretty vanilla.

Using sanoid/syncoid v2.0.3 (latest stable tag) via the latest Debian instructions.

According to those instructions I set up a systemd timer for sanoid, so it creates hourly snapshots. Here's a list of the snapshots created on my homes zpool:

# zfs list -t snapshot
NAME                                                           USED  AVAIL     REFER  MOUNTPOINT
homes/home@autosnap_2021-03-25_22:27:28_monthly                  0B      -      191G  -
...
homes/home@syncoid_hestia_2021-03-26:10:45:49                  345K      -      191G  -
homes/home@autosnap_2021-03-26_10:00:01_hourly                 339K      -      191G  -

The homes/home dataset is not encrypted:

# zfs list -o name,encryption homes/home
NAME        ENCRYPTION
homes/home  off

I want to send all snapshots of homes/home to my tank/backups/homes dataset. This dataset is encrypted:

# zfs list -o name,encryption tank/backups/homes
NAME                ENCRYPTION
tank/backups/homes  aes-256-gcm

I'm using the following command to send/receive these snapshots, assuming ZFS will create a child dataset in tank/backups/homes/home that inherits encryption from the parent tank/backups/homes:

# syncoid --debug homes/home tank/backups/homes/home

However, this command fails consistently with the following output:

# syncoid --debug homes/home tank/backups/homes/home
DEBUG: SSHCMD: ssh
DEBUG: checking availability of lzop on source...
DEBUG: checking availability of lzop on target...
DEBUG: checking availability of lzop on local machine...
DEBUG: checking availability of mbuffer on source...
DEBUG: checking availability of mbuffer on target...
DEBUG: checking availability of pv on local machine...
DEBUG: checking availability of zfs resume feature on source...
DEBUG: checking availability of zfs resume feature on target...
DEBUG: syncing source homes/home to target tank/backups/homes/home.
DEBUG: getting current value of syncoid:sync on homes/home...
  zfs get -H syncoid:sync 'homes/home'
DEBUG: checking to see if tank/backups/homes/home on  is already in zfs receive using  ps -Ao args= ...
DEBUG: checking to see if target filesystem exists using "  zfs get -H name 'tank/backups/homes/home' 2>&1 |"...
DEBUG: getting list of snapshots on homes/home using   zfs get -Hpd 1 -t snapshot guid,creation 'homes/home' |...
DEBUG: creating sync snapshot using "  zfs snapshot 'homes/home'@syncoid_hestia_2021-03-26:10:45:49
"...
DEBUG: target tank/backups/homes/home does not exist.  Finding oldest available snapshot on source homes/home ...
DEBUG: getting estimated transfer size from source  using "  zfs send  -nP 'homes/home@autosnap_2021-03-25_22:27:28_monthly' 2>&1 |"...
DEBUG: sendsize = 205354192152
INFO: Sending oldest full snapshot homes/home@autosnap_2021-03-25_22:27:28_monthly (~ 191.3 GB) to new target filesystem:
DEBUG:  zfs send  'homes/home'@'autosnap_2021-03-25_22:27:28_monthly' | mbuffer  -q -s 128k -m 16M 2>/dev/null | pv -s 205354192152 |  zfs receive  -s -F 'tank/backups/homes/home'
DEBUG: checking to see if tank/backups/homes/home on  is already in zfs receive using  ps -Ao args= ...
 194GiB 0:04:05 [ 813MiB/s] [==============================================================================================================================================================================================================================================================================================] 101%
DEBUG: getting estimated transfer size from source  using "  zfs send  -nP -I 'homes/home@autosnap_2021-03-25_22:27:28_monthly' 'homes/home@syncoid_hestia_2021-03-26:10:45:49' 2>&1 |"...
DEBUG: sendsize = 19133424
DEBUG: checking to see if tank/backups/homes/home on  is already in zfs receive using  ps -Ao args= ...
INFO: Updating new target filesystem with incremental homes/home@autosnap_2021-03-25_22:27:28_monthly ... syncoid_hestia_2021-03-26:10:45:49 (~ 18.2 MB):
DEBUG:  zfs send  -I 'homes/home'@'autosnap_2021-03-25_22:27:28_monthly' 'homes/home'@'syncoid_hestia_2021-03-26:10:45:49' | mbuffer  -q -s 128k -m 16M 2>/dev/null | pv -s 19133424 |  zfs receive  -s -F 'tank/backups/homes/home'
cannot receive incremental stream: dataset is busy
1.00MiB 0:00:01 [ 563KiB/s] [=============>                                                                                                                                                                                                                                                                                 ]  5%
mbuffer: error: outputThread: error writing to <stdout> at offset 0x130000: Broken pipe
mbuffer: warning: error during output to <stdout>: Broken pipe
CRITICAL ERROR:  zfs send  -I 'homes/home'@'autosnap_2021-03-25_22:27:28_monthly' 'homes/home'@'syncoid_hestia_2021-03-26:10:45:49' | mbuffer  -q -s 128k -m 16M 2>/dev/null | pv -s 19133424 |  zfs receive  -s -F 'tank/backups/homes/home' failed: 256 at /usr/sbin/syncoid line 500.

Issue #598 seems similar, although in that case a sendoption flag seems to have been the culprit. I'm not using those in my syncoid command – it's as vanilla as possible.

This post on the FreeBSD forum seems similar to my issue, in that I also see a clone on the received snapshot:

# zfs get all tank/backups/homes/home@autosnap_2021-03-25_22:27:28_monthly
NAME                                                          PROPERTY              VALUE                          SOURCE
tank/backups/homes/home@autosnap_2021-03-25_22:27:28_monthly  type                  snapshot                       -
tank/backups/homes/home@autosnap_2021-03-25_22:27:28_monthly  creation              Thu Mar 25 22:27 2021          -
...
tank/backups/homes/home@autosnap_2021-03-25_22:27:28_monthly  clones                tank/backups/homes/home/%recv  -
...

# zfs list tank/backups/homes/home/%recv
NAME                            USED  AVAIL     REFER  MOUNTPOINT
tank/backups/homes/home/%recv     0B  43.1T      102G  /mnt/backups/homes/home/%recv

Is this what triggers the error, or am I doing something wrong? Happy to provide additional output if needed!

Here's the version output for syncoid:

# syncoid --version
/usr/sbin/syncoid version 2.0.3
(Getopt::Long::GetOptions version 2.50; Perl version 5.28.1)

I'm running on Debian 10 (Buster):

# uname -a
Linux hestia 5.4.0-0.bpo.2-amd64 #1 SMP Debian 5.4.8-1~bpo10+1 (2020-01-07) x86_64 GNU/Linux

With this ZFS version:

# zfs --version
zfs-2.0.3-1~bpo10+1
zfs-kmod-2.0.3-1~bpo10+1

jimsalterjrs commented 3 years ago

This is going to (of necessity) be a ZFS issue, not a syncoid issue—ZFS is what's throwing that "dataset busy" error, syncoid is merely passing it along to you.

To figure out why the dataset is busy after that initial full replication (which succeeded, from looking at your report) you'll have to investigate on the target side. You might check lsof to see if anything's going on with filesystem locks inside the newly created dataset, for example.

If you can't figure anything out obvious there—locked files inside the dataset, etc—you'll probably need/want to open a bug with OpenZFS itself. If the project gets shirty about pointing fingers back at syncoid, you can simplify things by stripping the ZFS replication commands out of the syncoid output, and reproducing them manually. EG:

zfs send  -I 'homes/home'@'autosnap_2021-03-25_22:27:28_monthly' 'homes/home'@'syncoid_hestia_2021-03-26:10:45:49' | mbuffer  -q -s 128k -m 16M 2>/dev/null | pv -s 19133424 |  zfs receive  -s -F 'tank/backups/homes/home'

You can just run that exact command directly from the command line. You can also simplify it considerably, again for easier problem reporting upstream (and bisecting for potential problem points):

zfs send  -I 'homes/home'@'autosnap_2021-03-25_22:27:28_monthly' 'homes/home'@'syncoid_hestia_2021-03-26:10:45:49' |  pv -s 19133424 |  zfs receive  -s -F 'tank/backups/homes/home'

You can simplify even further by stripping out the pv command as well, but things may get painful if you do, due to the lack of progress bar letting you know where you sit in a potentially very long-running operation.

jimsalterjrs commented 3 years ago

It looks to me like there are some issues with replicating encrypted datasets, at the ZFS level. This isn't something I've personally done any testing on yet, but like you said it's a similar issue to #598 —and you're both working with encrypted datasets and replication.

marceldegraaf commented 3 years ago

Hey Jim – thanks for your detailed reply. Today I noticed my machine reporting severe memory issues with memtester so I'm going to fix that first, to make sure that isn't what was causing my ZFS issues.

phreaker0 commented 3 years ago

@marceldegraaf just tested an initial send/receive from a non-encrypted to an encrypted pool on debian 10 with syncoid and it works just fine, so it seems the problem is with your system

marceldegraaf commented 3 years ago

@phreaker0 how large was that initial send/receive? My suspicion is that ZFS is doing some work related to encryption after the initial send, which makes the dataset report as busy for large initial receives. My initial snapshot is ~191 GB in size.

I've been able to reproduce my issue with zfs send/receive, so without using syncoid. See below.

I'm OK with keeping this issue closed as the issue seems to be related to ZFS, not syncoid.

First I sent the initial snapshot to the encrypted destination:

zfs send 'homes/home@autosnap_2021-03-25_22:27:28_monthly' | pv -s 205354192152 | zfs receive -s -F 'tank/backups/homes/home'

And then, after a few minutes (because I had to look up the exact commands and send size for pv), an incremental send to the latest snapshot:

zfs send -I 'homes/home@autosnap_2021-03-25_22:27:28_monthly' 'homes/home@autosnap_2021-03-31_18:00:01_hourly' | pv -s 1659827952 | zfs receive -s -F 'tank/backups/homes/home'

This worked without issue. However, I then removed the tank/backups/homes/home dataset (and all its snapshots) to start with a clean slate, and simulated what syncoid does by immediately sending the incremental snapshots after the initial send is complete:

zfs send 'homes/home@autosnap_2021-03-25_22:27:28_monthly' | pv -s 205354192152 | zfs receive -s -F 'tank/backups/homes/home' && zfs send -I 'homes/home@autosnap_2021-03-25_22:27:28_monthly' 'homes/home@autosnap_2021-03-31_18:00:01_hourly' | pv -s 1659827952 | zfs receive -s -F 'tank/backups/homes/home'

Lo and behold: the same dataset is busy error as thrown from syncoid:

cannot receive incremental stream: dataset is busy

It seems ZFS is doing some work related to encryption after the initial send. To test this I created a new, non-encrypted dataset on tank/backups, and tried simulating syncoid again. That worked without issue.

Finally I tried running syncoid again, this time with the non-encrypted dataset as destination: syncoid --debug homes/home tank/backups/temp/home. That also worked without issue.

phreaker0 commented 3 years ago

@marceldegraaf ~19GB

interesting, but as you said it's mostly likely a zfs issue then.

marceldegraaf commented 3 years ago

Yes, we've at least ruled out syncoid as the culprit. Thanks for your help anyway!

MrRinkana commented 5 months ago

Isn't this a syncoid issue in the sense that syncoid should wait before sending the next dataset until the target pool is no longer busy? Or retry in some short while?

I suspect this happens mostly with slower storage/cpu targets.

In my case I'm sending a unencrypted dataset to a encrypted target (encrypting at target).

For me it looks like the issue appears when syncoid is trying to send the next dataset while zfs on the target is stuck with mounting the previously sent dataset. I only manage to get this error on initial/full syncs, which makes sense as mounting of the synced dataset only happens on initial sync, right?

Do we have any ZFS issue opened about this? I didn't find anything that looked like what is experienced here or experienced by me, except some issues with raw sends.. Or maybe this: https://github.com/openzfs/zfs/issues/6504 ?

phreaker0 commented 5 months ago

@MrRinkana syncoid can't properly detect if a zfs dataset is busy. It will attempt to do what it was instructed and zfs will throw an busy error if some other operation is already going on.

For me it looks like the issue appears when syncoid is trying to send the next dataset while zfs on the target is stuck with mounting the previously sent dataset. I only manage to get this error on initial/full syncs, which makes sense as mounting of the synced dataset only happens on initial sync, right?

AFAIK For ZFS mounting a dataset and receiving a dataset at the same time works.

MrRinkana commented 4 months ago

Hmm, okay thanks! But what operations could trigger dataset is busy then?

Would it still make sense to retry the last command with some minor delay if it exited with "dataset is busy"?

devosalain commented 3 months ago

Currently i'm trying with "sleep 60".

jimsalterjrs / sanoid

Latest stable syncoid fails on initial send/receive: cannot receive incremental stream: dataset is busy #629