Re: Backup failing with "failed to clone extents" error

[Filipe Manana <fdmanana@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 3028 bytes --]

On Tue, Aug 31, 2021 at 3:46 AM Darrell Enns <darrell@darrellenns.com> wrote:
>
> Debug output from the latest patch attached. Here's the error:
> BTRFS info (device dm-3): clone: -EINVAL other, src 400186 (root 2792)
> dst 400186 (root 2792), off 79134720 destoff 79134720 len 4751360 olen
> 4751360, src i_size 83886080 dst i_size 83886080 bs 4096 remap_flags 0

Yep, the same weird thing as before.

So the receiving filesystem gets that error, which is perfectly valid
since we are asking to clone from the same inode to the same inode in
the same root (snapshot) with the same source and destination offsets
- source range and target range overlap, whence the error.

However, if we go the dmesg log:

[   99.834090] BTRFS info (device dm-0): send: clone_range() start ino
400698 offset 79134720 send root 977, clone root 881 ino 400698 offset
79134720 data_offset 491520 len 4751360 disk_byte 308100730880
clone_src_i_size 83886080 next_write_offset 79134720
[   99.834094] BTRFS info (device dm-0): send: clone_range() step 1
ino 400698 offset 79134720, root offset 79134720 ino 400698
data_offset 491520 len 4751360, key.offset 78675968 ext_len 5210112
clone_data_offset 32768 found disk_byte 308100730880 next_write_offset
79134720
[   99.834096] BTRFS info (device dm-0): send: clone_range() step
2-1-2 ino 400698 offset 79134720, root offset 79134720 ino 400698
data_offset 491520 len 4751360, clone_len 4751360
[   99.834112] BTRFS info (device dm-0): send: clone_range() end ino
400698 offset 79134720 send root 977, clone root 881 ino 400698 offset
79134720 data_offset 491520 len 0 disk_byte 308100730880
clone_src_i_size 83886080 next_write_offset 79134720 ret 0

We see that send is issuing a clone command using different roots
(snapshots) for the clone operation (send root is 977 and clone root
is 881).
The root/snapshot IDs are different in the source and destination
filesystems - that's normal and it's what happens most of the time.
However I don't understand how is the inode number different, nor much
less how the receiver attempts to use the same root/snapshot as both
the source and destination for the clone operation - it should use
different roots/snapshots.

Ok, so, here's another kernel debug patch and also a patch for
btrfs-progs, both added as attachments.

The kernel one also at:  https://pastebin.com/raw/nfHfRuy7
And the progs one also at:  https://pastebin.com/raw/9CbN9C0H

When you run 'btrfs receive', you'll have to pass '-vvv' to it in
order to get the debug output.

Also, please provide the output of:

1) btrfs subvolume list -puqR <source fs mount path>
2) btrfs subvolume list -puqR <destination fs mount path>
3) cat /proc/mounts

I'm starting to suspect that somewhere, possibly the receiving side,
we make confusion with the snapshot uuids or generate wrong paths for
the clone operation.

Thanks!



-- 
Filipe David Manana,

“Whether you think you can, or you think you can't — you're right.”

[-- Attachment #2: debug_send_clone_3.patch --]
[-- Type: text/x-patch, Size: 8089 bytes --]

diff --git a/fs/btrfs/reflink.c b/fs/btrfs/reflink.c
index 4a5f2c35c034..a4a00db9d547 100644
--- a/fs/btrfs/reflink.c
+++ b/fs/btrfs/reflink.c
@@ -780,6 +780,13 @@ static int btrfs_remap_file_range_prep(struct file *file_in, loff_t pos_in,
 	/* Don't make the dst file partly checksummed */
 	if ((BTRFS_I(inode_in)->flags & BTRFS_INODE_NODATASUM) !=
 	    (BTRFS_I(inode_out)->flags & BTRFS_INODE_NODATASUM)) {
+		if (!(remap_flags & REMAP_FILE_DEDUP)) {
+			struct btrfs_fs_info *fs_info = BTRFS_I(inode_in)->root->fs_info;
+
+			btrfs_info(fs_info, "clone: nodatasum mismatch, src %llu (root %llu) dst %llu (root %llu)",
+				   btrfs_ino(BTRFS_I(inode_in)), BTRFS_I(inode_in)->root->root_key.objectid,
+				   btrfs_ino(BTRFS_I(inode_out)), BTRFS_I(inode_out)->root->root_key.objectid);
+		}
 		return -EINVAL;
 	}
 
@@ -863,9 +870,16 @@ loff_t btrfs_remap_file_range(struct file *src_file, loff_t off,
 	struct inode *dst_inode = file_inode(dst_file);
 	bool same_inode = dst_inode == src_inode;
 	int ret;
-
-	if (remap_flags & ~(REMAP_FILE_DEDUP | REMAP_FILE_ADVISORY))
+	struct btrfs_fs_info *fs_info = BTRFS_I(src_inode)->root->fs_info;
+	const loff_t olen = len;
+
+	if (remap_flags & ~(REMAP_FILE_DEDUP | REMAP_FILE_ADVISORY)) {
+		btrfs_info(fs_info, "clone: -EINVAL flags, src %llu (root %llu) dst %llu (root %llu), off %lld destoff %lld len %lld olen %lld, src i_size %lld dst i_size %lld bs %lu remap_flags %u",
+			   btrfs_ino(BTRFS_I(src_inode)), BTRFS_I(src_inode)->root->root_key.objectid,
+			   btrfs_ino(BTRFS_I(dst_inode)), BTRFS_I(dst_inode)->root->root_key.objectid,
+			   off, destoff, len, olen, i_size_read(src_inode), i_size_read(dst_inode), dst_inode->i_sb->s_blocksize, remap_flags);
 		return -EINVAL;
+	}
 
 	if (same_inode) {
 		btrfs_inode_lock(src_inode, BTRFS_ILOCK_MMAP);
@@ -876,6 +890,11 @@ loff_t btrfs_remap_file_range(struct file *src_file, loff_t off,
 
 	ret = btrfs_remap_file_range_prep(src_file, off, dst_file, destoff,
 					  &len, remap_flags);
+	if (ret == -EINVAL && !(remap_flags & REMAP_FILE_DEDUP))
+		btrfs_info(fs_info, "clone: -EINVAL other, src %llu (root %llu) dst %llu (root %llu), off %lld destoff %lld len %lld olen %lld, src i_size %lld dst i_size %lld bs %lu remap_flags %u",
+			   btrfs_ino(BTRFS_I(src_inode)), BTRFS_I(src_inode)->root->root_key.objectid,
+			   btrfs_ino(BTRFS_I(dst_inode)), BTRFS_I(dst_inode)->root->root_key.objectid,
+			   off, destoff, len, olen, i_size_read(src_inode), i_size_read(dst_inode), dst_inode->i_sb->s_blocksize, remap_flags);
 	if (ret < 0 || len == 0)
 		goto out_unlock;
 
diff --git a/fs/btrfs/send.c b/fs/btrfs/send.c
index afdcbe7844e0..25893e17a95b 100644
--- a/fs/btrfs/send.c
+++ b/fs/btrfs/send.c
@@ -5037,6 +5037,7 @@ static int send_clone(struct send_ctx *sctx,
 {
 	int ret = 0;
 	struct fs_path *p;
+	struct fs_path *p2;
 	u64 gen;
 
 	btrfs_debug(sctx->send_root->fs_info,
@@ -5044,9 +5045,18 @@ static int send_clone(struct send_ctx *sctx,
 		    offset, len, clone_root->root->root_key.objectid,
 		    clone_root->ino, clone_root->offset);
 
+	WARN_ON(clone_root->root == sctx->send_root &&
+		clone_root->ino == sctx->cur_ino &&
+		clone_root->offset == offset);
+
 	p = fs_path_alloc();
 	if (!p)
 		return -ENOMEM;
+	p2 = fs_path_alloc();
+	if (!p2) {
+		fs_path_free(p);
+		return -ENOMEM;
+	}
 
 	ret = begin_cmd(sctx, BTRFS_SEND_C_CLONE);
 	if (ret < 0)
@@ -5056,6 +5066,8 @@ static int send_clone(struct send_ctx *sctx,
 	if (ret < 0)
 		goto out;
 
+	fs_path_copy(p2, p);
+
 	TLV_PUT_U64(sctx, BTRFS_SEND_A_FILE_OFFSET, offset);
 	TLV_PUT_U64(sctx, BTRFS_SEND_A_CLONE_LEN, len);
 	TLV_PUT_PATH(sctx, BTRFS_SEND_A_PATH, p);
@@ -5093,11 +5105,21 @@ static int send_clone(struct send_ctx *sctx,
 	TLV_PUT_U64(sctx, BTRFS_SEND_A_CLONE_OFFSET,
 			clone_root->offset);
 
+	btrfs_info(sctx->send_root->fs_info,
+		   "send_clone: ino %llu clone_ino %llu send_root %llu clone_root %llu offset %llu clone_offset %llu ino_path %s clone_path %s send_root_uuid %pU send_root_received_uuid %pU clone_root_uuid %pU clone_root_received_uuid %pU",
+		   sctx->cur_ino, clone_root->ino, sctx->send_root->root_key.objectid,
+		   clone_root->root->root_key.objectid, offset, clone_root->offset,
+		   p2->start, p->start, sctx->send_root->root_item.uuid,
+		   sctx->send_root->root_item.received_uuid,
+		   clone_root->root->root_item.uuid,
+		   clone_root->root->root_item.received_uuid);
+
 	ret = send_cmd(sctx);
 
 tlv_put_failure:
 out:
 	fs_path_free(p);
+	fs_path_free(p2);
 	return ret;
 }
 
@@ -5280,6 +5302,7 @@ static int clone_range(struct send_ctx *sctx,
 	struct btrfs_key key;
 	int ret;
 	u64 clone_src_i_size = 0;
+	struct btrfs_fs_info *fs_info = sctx->send_root->fs_info;
 
 	/*
 	 * Prevent cloning from a zero offset with a length matching the sector
@@ -5349,6 +5372,10 @@ static int clone_range(struct send_ctx *sctx,
 			path->slots[0]--;
 	}
 
+	btrfs_info(fs_info, "send: clone_range() start ino %llu offset %llu send root %llu, clone root %llu ino %llu offset %llu data_offset %llu len %llu disk_byte %llu clone_src_i_size %llu next_write_offset %llu",
+		   sctx->cur_ino, offset, sctx->send_root->root_key.objectid, clone_root->root->root_key.objectid, clone_root->ino, clone_root->offset, data_offset, len,
+		   disk_byte, clone_src_i_size, sctx->cur_inode_next_write_offset);
+
 	while (true) {
 		struct extent_buffer *leaf = path->nodes[0];
 		int slot = path->slots[0];
@@ -5417,6 +5444,11 @@ static int clone_range(struct send_ctx *sctx,
 			ext_len = clone_src_i_size - key.offset;
 
 		clone_data_offset = btrfs_file_extent_offset(leaf, ei);
+
+		btrfs_info(fs_info, "send: clone_range() step 1 ino %llu offset %llu, root offset %llu ino %llu data_offset %llu len %llu, key.offset %llu ext_len %llu clone_data_offset %llu found disk_byte %llu next_write_offset %llu",
+			   sctx->cur_ino, offset, clone_root->offset, clone_root->ino, data_offset, len, key.offset, ext_len, clone_data_offset, btrfs_file_extent_disk_bytenr(leaf, ei),
+			   sctx->cur_inode_next_write_offset);
+
 		if (btrfs_file_extent_disk_bytenr(leaf, ei) == disk_byte) {
 			clone_root->offset = key.offset;
 			if (clone_data_offset < data_offset &&
@@ -5462,6 +5494,9 @@ static int clone_range(struct send_ctx *sctx,
 
 				slen = ALIGN_DOWN(src_end - clone_root->offset,
 						  sectorsize);
+				btrfs_info(fs_info, "send: clone_range() step 2-1-1 ino %llu offset %llu, root offset %llu ino %llu data_offset %llu len %llu, clone_len %llu src_end %llu slen %llu",
+					   sctx->cur_ino, offset, clone_root->offset, clone_root->ino, data_offset, len, clone_len, src_end, slen);
+
 				if (slen > 0) {
 					ret = send_clone(sctx, offset, slen,
 							 clone_root);
@@ -5471,10 +5506,15 @@ static int clone_range(struct send_ctx *sctx,
 				ret = send_extent_data(sctx, offset + slen,
 						       clone_len - slen);
 			} else {
+				btrfs_info(fs_info, "send: clone_range() step 2-1-2 ino %llu offset %llu, root offset %llu ino %llu data_offset %llu len %llu, clone_len %llu",
+					   sctx->cur_ino, offset, clone_root->offset, clone_root->ino, data_offset, len, clone_len);
+
 				ret = send_clone(sctx, offset, clone_len,
 						 clone_root);
 			}
 		} else {
+			btrfs_info(fs_info, "send: clone_range() step 2-2 ino %llu offset %llu, root offset %llu ino %llu data_offset %llu len %llu clone_len %llu",
+				   sctx->cur_ino, offset, clone_root->offset, clone_root->ino, data_offset, len, clone_len);
 			ret = send_extent_data(sctx, offset, clone_len);
 		}
 
@@ -5511,6 +5551,10 @@ static int clone_range(struct send_ctx *sctx,
 	else
 		ret = 0;
 out:
+	btrfs_info(fs_info, "send: clone_range() end ino %llu offset %llu send root %llu, clone root %llu ino %llu offset %llu data_offset %llu len %llu disk_byte %llu clone_src_i_size %llu next_write_offset %llu ret %d",
+		   sctx->cur_ino, offset, sctx->send_root->root_key.objectid, clone_root->root->root_key.objectid, clone_root->ino, clone_root->offset, data_offset, len,
+		   disk_byte, clone_src_i_size, sctx->cur_inode_next_write_offset, ret);
+
 	btrfs_free_path(path);
 	return ret;
 }

[-- Attachment #3: btrfs-progs_debug_receive.patch --]
[-- Type: text/x-patch, Size: 836 bytes --]

diff --git a/cmds/receive.c b/cmds/receive.c
index 4dd01fd3..0e285d3d 100644
--- a/cmds/receive.c
+++ b/cmds/receive.c
@@ -781,6 +781,16 @@ static int process_clone(const char *path, u64 offset, u64 len,
 			"clone %s - source=%s source offset=%llu offset=%llu length=%llu\n",
 			path, clone_path, clone_offset, offset, len);
 
+	if (bconf.verbose >= 2) {
+		char uuid_str_1[BTRFS_UUID_UNPARSED_SIZE];
+		char uuid_str_2[BTRFS_UUID_UNPARSED_SIZE];
+
+		uuid_unparse(clone_uuid, uuid_str_1);
+		uuid_unparse(rctx->cur_subvol.received_uuid, uuid_str_2);
+		fprintf(stderr, "clone_uuid=%s received_uuid=%s full_clone_path=%s root_path=%s full_path=%s\n",
+			uuid_str_1, uuid_str_2, full_clone_path, rctx->root_path, full_path);
+	}
+
 	clone_args.src_fd = clone_fd;
 	clone_args.src_offset = clone_offset;
 	clone_args.src_length = len;