Backup failing with "failed to clone extents" error

From: Matt Huszagh <huszaghmatt@gmail.com>
To: linux-btrfs@vger.kernel.org
Subject: Backup failing with "failed to clone extents" error
Date: Wed, 15 Apr 2020 17:31:57 -0700	[thread overview]
Message-ID: <87blnsuv7m.fsf@gmail.com> (raw)

I'm attempting to perform a backup to an external hard drive. Both the
native drive and external drive use a BTRFS filesystem. I do this by
first creating a read-only snapshot of my home directory:

# btrfs subvolume snapshot -r /home /.snapshots/home/BACKUP

Followed by a send/receive to the backup drive:

# btrfs send /.snapshots/home/BACKUP | btrfs receive /.backup/home

I get this output:

At subvol /.snapshots/home/BACKUP
At subvol BACKUP
ERROR: failed to clone extents to matt/.local/share/Anki2/Matt/collection.anki2: Invalid argument

There several files that trigger this error (most of them .sqlite
files). I can delete the offending files, which causes the backup to
work. However, new offending files are created that recreate the error
(e.g. Firefox generates lots of offending .sqlite files).

I performed

# btrfs scrub start -B /

which exited without errors and failed to resolve the issue and I even
ran check --repair on my filesystem unmounted:

# btrfs check --repair /dev/mapper/...

which didn't make a difference.

uname -a:
Linux ryzen3950 5.5.0 #1-NixOS SMP Mon Jan 27 00:23:03 UTC 2020 x86_64 GNU/Linux

btrfs --version
btrfs-progs v5.4.1

btrfs fi show
Label: 'btrfs'  uuid: d31878d6-3a77-4f0f-9fdd-bb9a2c4e578b
        Total devices 2 FS bytes used 737.53GiB
        devid    1 size 931.01GiB used 853.03GiB path /dev/mapper/cryptnvme
        devid    2 size 931.50GiB used 853.03GiB path /dev/mapper/cryptnvme1

Label: 'backup'  uuid: 0bd10808-0330-4736-9425-059d4a0a300e
        Total devices 2 FS bytes used 473.34GiB
        devid    1 size 1.82TiB used 475.01GiB path /dev/mapper/cryptsda1
        devid    2 size 1.82TiB used 475.01GiB path /dev/mapper/cryptsdb1

btrfs fi df /
Data, RAID0: total=1.44TiB, used=730.13GiB
System, RAID1: total=32.00MiB, used=144.00KiB
Metadata, RAID1: total=20.00GiB, used=7.40GiB
GlobalReserve, single: total=512.00MiB, used=0.00B

Here's the output of dmesg. I've only taken the lines containing
dmesg. Please let me know if this is insufficient and I'll provide the
full log.

[    1.168132] stage-1-init: loading module btrfs...
[    1.442869] Btrfs loaded, crc32c=crc32c-intel
[   14.552850] BTRFS: device label backup devid 2 transid 303 /dev/mapper/cryptsdb1 scanned by btrfs (857)
[   14.553396] BTRFS: device label backup devid 1 transid 303 /dev/mapper/cryptsda1 scanned by btrfs (857)
[   14.553487] BTRFS: device label btrfs devid 2 transid 409463 /dev/mapper/cryptnvme1 scanned by btrfs (857)
[   14.553573] BTRFS: device label btrfs devid 1 transid 409463 /dev/mapper/cryptnvme scanned by btrfs (857)
[   14.553634] stage-1-init: Scanning for Btrfs filesystems
[   14.561445] BTRFS info (device dm-0): use lzo compression, level 0
[   14.561447] BTRFS info (device dm-0): enabling ssd optimizations
[   14.561447] BTRFS info (device dm-0): disk space caching is enabled
[   14.561448] BTRFS info (device dm-0): has skinny extents
[   14.637769] BTRFS info (device dm-0): checking UUID tree
[   14.786327] BTRFS info (device dm-0): disk space caching is enabled
[   15.926714] BTRFS info (device dm-0): device fsid d31878d6-3a77-4f0f-9fdd-bb9a2c4e578b devid 1 moved old:/dev/mapper/cryptnvme new:/dev/dm-0
[   15.926763] BTRFS info (device dm-0): device fsid d31878d6-3a77-4f0f-9fdd-bb9a2c4e578b devid 2 moved old:/dev/disk/by-uuid/d31878d6-3a77-4f0f-9fdd-bb9a2c4e578b new:/dev/dm-1
[   16.043567] BTRFS info (device dm-0): disk space caching is enabled
[   16.074722] BTRFS info (device dm-2): use lzo compression, level 0
[   16.074723] BTRFS info (device dm-2): disk space caching is enabled
[   16.074724] BTRFS info (device dm-2): has skinny extents
[27057.785935] BTRFS info (device dm-0): scrub: started on devid 1
[27057.800078] BTRFS info (device dm-0): scrub: started on devid 2
[27107.287558] BTRFS info (device dm-0): scrub: not finished on devid 1 with status: -125
[27107.316437] BTRFS info (device dm-0): scrub: not finished on devid 2 with status: -125
[27109.542589] BTRFS info (device dm-0): scrub: started on devid 1
[27109.556751] BTRFS info (device dm-0): scrub: started on devid 2
[27243.975463] BTRFS info (device dm-0): scrub: finished on devid 1 with status: 0
[27247.857511] BTRFS info (device dm-0): scrub: finished on devid 2 with status: 0
[250470.993201] [  23284]     0 23284     3204       25    45056        0             0 btrfs
[250470.993203] [  23286]     0 23286     1155       53    40960        0             0 btrfs

Thanks!
Matt