Re: btrfs send -p failing: chown o257-1571-0 failed: No such file or directory

From: Filipe Manana <fdmanana@gmail.com>
To: "Massimo B." <massimo.b@gmx.net>
Cc: linux-btrfs <linux-btrfs@vger.kernel.org>
Subject: Re: btrfs send -p failing: chown o257-1571-0 failed: No such file or directory
Date: Mon, 11 Jan 2021 11:49:46 +0000	[thread overview]
Message-ID: <CAL3q7H5WX8wo=i_rPQ_kU+Qzup1qxQ7U=2LKO0BstrSkGCUfmw@mail.gmail.com> (raw)
In-Reply-To: <CAL3q7H7EoyQ+_kf0R04TwDZHSWnDH6fojYviryYTjgPuRc4HfA@mail.gmail.com>

On Fri, Dec 18, 2020 at 11:44 AM Filipe Manana <fdmanana@gmail.com> wrote:
>
> On Fri, Dec 18, 2020 at 7:25 AM Massimo B. <massimo.b@gmx.net> wrote:
> >
> > On Mon, 2020-12-14 at 09:46 +0000, Filipe Manana wrote:
> >
> > > clone mb/Documents.AZ/0.SYNC/....pdf - source=mb/Documents.AZ/0.SYNC/....pdf
> > > > source offset=20705280 offset=20709376 length=4096
> > > > clone mb/Documents.AZ/0.SYNC/....pdf - source=mb/Documents.AZ/0.SYNC/....pdf
> > > > source offset=20713472 offset=20713472 length=4096
> > > > ERROR: failed to clone extents to mb/Documents.AZ/0.SYNC/....pdf: Invalid
> > > > argument
> > >
> > > It's a different problem. This one because the kernel is sending an
> > > invalid clone operation - the source and destination offsets are the
> > > same, which makes the receiver fail.
> > > Can you tell what's the size (in bytes) of "mb/Documents.AZ/0.SYNC"
> > > after the receive fails? Both in the destination and source.
> >
> > Hi Filipe,
> >
> > I already deleted the failing subvolume, now I got the issue again. Here are the
> > detailed information about the file:
> >
> >
> > # btrfs send /mnt/usb/mobiledata/snapshots/mobalindesk/vm/VirtualMachines.20190621T140904+0200 | mbuffer -v 1 -m 2% | btrfs receive /mnt/local/data/snapshots/vm/
> > ...
> > write IE8 - Win7/IE8 - Win7-disk1.vmdk - offset=4742344704 length=4096
> > clone IE8 - Win7/IE8 - Win7-disk1.vmdk - source=IE8 - Win7/IE8 - Win7-disk1.vmdk source offset=4742184960 offset=4742348800 length=16384
> > clone IE8 - Win7/IE8 - Win7-disk1.vmdk - source=IE8 - Win7/IE8 - Win7-disk1.vmdk source offset=4742184960 offset=4742365184 length=28672
> > clone IE8 - Win7/IE8 - Win7-disk1.vmdk - source=IE8 - Win7/IE8 - Win7-disk1.vmdk source offset=4742246400 offset=4742393856 length=8192
> > write IE8 - Win7/IE8 - Win7-disk1.vmdk - offset=4742402048 length=12288
> > clone IE8 - Win7/IE8 - Win7-disk1.vmdk - source=IE8 - Win7/IE8 - Win7-disk1.vmdk source offset=4742410240 offset=4742414336 length=4096
> > clone IE8 - Win7/IE8 - Win7-disk1.vmdk - source=IE8 - Win7/IE8 - Win7-disk1.vmdk source offset=4742418432 offset=4742418432 length=4096
> > ERROR: failed to clone extents to IE8 - Win7/IE8 - Win7-disk1.vmdk: Invalid argument
> >
> > summary: 4226 MiByte in 21min 11.4sec - average of 3404 kiB/s
> >
> >
> > # ls -al "/mnt/usb/mobiledata/snapshots/mobalindesk/vm/VirtualMachines.20190621T140904+0200/IE8 - Win7/IE8 - Win7-disk1.vmdk"
> > -rw------- 1 massimo massimo 17932222464 18. Dez 2018  '/mnt/usb/mobiledata/snapshots/mobalindesk/vm/VirtualMachines.20190621T140904+0200/IE8 - Win7/IE8 - Win7-disk1.vmdk'
> >
> > # ls -al "/mnt/local/data/snapshots/vm/VirtualMachines.20190621T140904+0200/IE8 - Win7/IE8 - Win7-disk1.vmdk"
> > -rw------- 1 root root 4742418432 18. Dez 07:37 '/mnt/local/data/snapshots/vm/VirtualMachines.20190621T140904+0200/IE8 - Win7/IE8 - Win7-disk1.vmdk'
> >
> > # compsize "/mnt/usb/mobiledata/snapshots/mobalindesk/vm/VirtualMachines.20190621T140904+0200/IE8 - Win7/IE8 - Win7-disk1.vmdk"
> > Type       Perc     Disk Usage   Uncompressed Referenced
> > TOTAL       45%      7.3G          16G          16G
> > none       100%      1.9G         1.9G         2.3G
> > zlib        38%      4.8G          12G          13G
> > zstd        34%      536M         1.5G         727M
> >
> > # compsize "/mnt/local/data/snapshots/vm/VirtualMachines.20190621T140904+0200/IE8 - Win7/IE8 - Win7-disk1.vmdk"
> > Type       Perc     Disk Usage   Uncompressed Referenced
> > TOTAL       92%      4.1G         4.4G         4.3G
> > none       100%      3.8G         3.8G         3.8G
> > zlib        32%      7.3M          22M          22M
> > zstd        45%      264M         583M         560M
> >
> > Does that help you?
>
> It confirms what I suspected and narrows down a bit the possible causes.
> Are you able to run the send operation again with the following debug path?
>
> https://pastebin.com/raw/cEEy9A6W

Well, never mind, in the meanwhile after the holidays I find out why it happens.
The patch with the fix is at:

https://patchwork.kernel.org/project/linux-btrfs/patch/900493c40f7edbd42fe861ccd9a68851ea952499.1610363502.git.fdmanana@suse.com/

Thanks.

>
> When the issue happens it should dump to dmesg/syslog a debug message
> that starts with the marker "HERE" and right before it,
> something that takes several lines to dump a metadata leaf, and with
> first line being something like this:
>
> "leaf <number> gen <number> total ptrs <number> free space <number>
> owner <number>"
>
> That way I can see the specific extent metadata layout that causes
> send to issue an invalid clone operation (attempting to clone 4096
> bytes from eof).
>
> Thanks a lot Massimo!
>
> >
> > Best regards,
> > Massimo
> >
>
>
> --
> Filipe David Manana,
>
> “Whether you think you can, or you think you can't — you're right.”

-- 
Filipe David Manana,

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