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

[Filipe Manana <fdmanana@gmail.com>]

On Tue, Aug 31, 2021 at 5:48 PM Darrell Enns <darrell@darrellenns.com> wrote:
>
> It's btrfs-progs v5.13.1. Debug logs are attached.

Ok, now I see what's going on.

Somehow you have at least two snapshots (with IDs 881 and 977 on the
send filesystem), that have the same 'received_uuid' -
e346e5a1-536c-8d42-ba33-c5452dec7888.
So these snapshots were received from some other filesystem in the past.

What's unusual is that they have different content - this suggests that maybe:

1) 881 was successfully sent to the destination filesystem (perhaps as
a full send, or as an incremental, doesn't matter);

2) 977 was turned from RO mode to RW mode, some changes made to it
(several writes to the sqlite file at least), turned back to RO mode
and then used for the incremental send operation.
Or that 977 was a RW snapshot of 881, then changed, someone called the
BTRFS_IOC_SET_RECEIVED_SUBVOL ioctl to set the received_uuid of the
snapshot to e346e5a1-536c-8d42-ba33-c5452dec7888, then turned it RO
and then used it for the incremental send.

Looking at the beginning of 'receive -vvv' output, shows:

At subvol /.snapshots/374/snapshot/
receiving snapshot snapshot uuid=e346e5a1-536c-8d42-ba33-c5452dec7888,
ctransid=39921 parent_uuid=e346e5a1-536c-8d42-ba33-c5452dec7888,
parent_ctransid=35384

The send snapshot and the parent snapshot have the same UUID. This is
asking for trouble, and in this case it causes problems.

And the sending side:

[  391.131006] 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
(...)
[  391.131025] BTRFS info (device dm-0): send_clone: ino 400698
clone_ino 400698 send_root 977 clone_root 881 offset 79134720
clone_offset 79134720 ino_path
home/denns/.mozilla/firefox/dtfto95g.default/places.sqlite clone_path
home/denns/.mozilla/firefox/dtfto95g.default/places.sqlite
send_root_uuid ab408d81-05ac-c346-a99a-f525d907c532
send_root_received_uuid e346e5a1-536c-8d42-ba33-c5452dec7888
clone_root_uuid fb2c8e58-2ffa-ad4e-9e0e-9b494691db63
clone_root_received_uuid e346e5a1-536c-8d42-ba33-c5452dec7888

We confirm that send root and parent roots have the same
received_uuid, which is e346e5a1-536c-8d42-ba33-c5452dec7888.
This results in the kernel sending a clone operation with a source
snapshot of e346e5a1-536c-8d42-ba33-c5452dec7888.

The kernel's intention is to emit a clone operation from the parent to
the send snapshot, using valid offsets and lengths.

But because both snapshots have the same received_uuid value, the
receiver picks the first snapshot it finds with a received_uuid of
e346e5a1-536c-8d42-ba33-c5452dec7888 as the source for the clone
operation - but it picks the snapshot that is being received, and not
the parent snapshot - in this case the clone operation is invalid as
we try to clone from the same inode to itself using the range as a
source and destination.

Having two different snapshots with the same received_uuid but
different content is unexpected and breaks send/receive.

I wonder how you managed to get two different snapshots, with the same
received_uuid and different content.




-- 
Filipe David Manana,

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