Unexpected "ERROR: clone: did not find source subvol" on btrfs receive

Unexpected "ERROR: clone: did not find source subvol" on btrfs receive

[Alexander Wetzel]

Hello,

I have a strange problem with btrfs send/receive.
While I can create incremental snaphosts but when I try to restore them
I reproducible get:

 > At snapshot 2021-02-20-TEMP
 > ERROR: clone: did not find source subvol

I've no "real" problem by that. Just want to report the issue so someone 
with more btrfs knowledge can dig into what went wrong here. After all 
that looks like a bug...

So I plan to keep it as it is for some more days and then play around to 
get incremental send/receive working again.

Here the procedure how I can reproduce the issue:

At start I have the following snapshots in the root of the affected file 
system. (Subvol "active is mounted as / and the btrfs root on 
/mnt/backup/backupdev):

active		<- the live RW filesystem
2021-02-14	<- a RO snapshot of the above from some days ago

And these steps reproducible are failing on btrfs recive:

1) create a new RO snapshot of active
# btrfs sub snap -r active/ 2021-02-20-TEMP
Create a readonly snapshot of 'active/' in './2021-02-20-TEMP'

2) btrfs send with 2021-02-14 as parent into test2
# btrfs send -p 2021-02-14 2021-02-20-TEMP -f test2
At subvol 2021-02-20-TEMP

3) remove the snapshot 2021-02-20-TEMP
# btrfs sub del 2021-02-20-TEMP
Delete subvolume (no-commit): '/mnt/backup/backupdev/2021-02-20-TEMP'

4) and try to import it again from test2
# btrfs receive -f test2 .
At snapshot 2021-02-20-TEMP
ERROR: clone: did not find source subvol

The same procedure is working for another btrfs filesystem on the same 
system.

The system is an Ubuntu 20.04 (kernel 5.4.0-65-generic, btrfs-progs v5.4.1).

And here some more information which may be useful:

# btrfs sub show active
active
         Name:                   active
         UUID:                   a2ff485b-9f8f-2543-ad03-dc7c917e143b
         Parent UUID:            6da3d5ab-4d9f-4805-b77e-0eab8ce2abc8
         Received UUID:          -
         Creation time:          2020-11-08 13:58:23 +0100
         Subvolume ID:           264
         Generation:             206432
         Gen at creation:        167
         Parent ID:              5
         Top level ID:           5
         Flags:                  -
         Snapshot(s):

# btrfs sub show 2021-02-14
2021-02-14
         Name:                   2021-02-14
         UUID:                   d31d553f-0917-3c48-b65c-ec51fd0c6d89
         Parent UUID:            a2ff485b-9f8f-2543-ad03-dc7c917e143b
         Received UUID:          -
         Creation time:          2021-02-14 21:46:26 +0100
         Subvolume ID:           358
         Generation:             206378
         Gen at creation:        195056
         Parent ID:              5
         Top level ID:           5
         Flags:                  readonly
         Snapshot(s):

# btrfs sub show 2021-02-20-TEMP
2021-02-20-TEMP
         Name:                   2021-02-20-TEMP
         UUID:                   120113e6-f83c-b240-ba27-259be4c92ea7
         Parent UUID:            a2ff485b-9f8f-2543-ad03-dc7c917e143b
         Received UUID:          -
         Creation time:          2021-02-20 18:06:29 +0100
         Subvolume ID:           375
         Generation:             206770
         Gen at creation:        206770
         Parent ID:              5
         Top level ID:           5
         Flags:                  readonly
         Snapshot(s):


# time btrfs receive -v -f test2 .
receiving snapshot 2021-02-20-TEMP 
uuid=120113e6-f83c-b240-ba27-259be4c92ea7, ctransid=206769 
parent_uuid=d31d553f-0917-3c48-b65c-ec51fd0c6d89, parent_ctransid=195056
write var/log/lastlog - offset=290816 length=4096
write var/log/wtmp - offset=122880 length=4096
write var/log/wtmp - offset=126976 length=4096
write var/log/wtmp - offset=131072 length=4096
write var/log/wtmp - offset=135168 length=384
write boot/grub/grubenv - offset=0 length=1024
write var/lib/systemd/random-seed - offset=0 length=512
write var/log/cloud-init.log - offset=1138688 length=49152
write var/log/cloud-init.log - offset=1187840 length=11555
write var/log/cloud-init-output.log - offset=53248 length=5329
write var/lib/cloud/instances/iid-datasource-none/datasource - offset=0 
length=31
write var/lib/cloud/data/previous-datasource - offset=0 length=31
write var/lib/cloud/data/instance-id - offset=0 length=20
write var/lib/cloud/data/previous-instance-id - offset=0 length=20
write var/lib/cloud/instances/iid-datasource-none/obj.pkl - offset=0 
length=8107
write var/lib/cloud/instances/iid-datasource-none/user-data.txt - 
offset=0 length=356
write var/lib/cloud/instances/iid-datasource-none/user-data.txt.i - 
offset=0 length=661
write var/lib/cloud/instances/iid-datasource-none/vendor-data.txt.i - 
offset=0 length=308
write var/lib/cloud/instances/iid-datasource-none/cloud-config.txt - 
offset=0 length=435
write var/cache/motd-news - offset=0 length=184
<removed 10200 lines>
write var/lib/mysql/mysql/innodb_index_stats.ibd - offset=393216 
length=16384
write var/lib/mysql/mysql/innodb_index_stats.ibd - offset=409600 
length=16384
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=0 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=8192 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=16384 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=24576 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=40960 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=49152 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=114688 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=155648 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=180224 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=212992 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=229376 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=253952 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=278528 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=294912 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=319488 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=385024 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=483328 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=516096 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=720896 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=729088 length=8192
write var/lib/mysql/nextcloud/oc_activity.ibd - offset=737280 length=8192
ERROR: clone: did not find source subvol
At snapshot 2021-02-20-TEMP

real    0m0.741s
user    0m0.246s
sys     0m0.127s


Noteworthy here is, that var/lib/mysql/ has set "chattr +C" set:

# lsattr 2021-02-20-TEMP/var/lib/mysql
---------------C---- 2021-02-20-TEMP/var/lib/mysql/aria_log.00000001
---------------C---- 2021-02-20-TEMP/var/lib/mysql/aria_log_control
---------------C---- 2021-02-20-TEMP/var/lib/mysql/debian-10.3.flag
---------------C---- 2021-02-20-TEMP/var/lib/mysql/ib_logfile0
---------------C---- 2021-02-20-TEMP/var/lib/mysql/ib_logfile1
---------------C---- 2021-02-20-TEMP/var/lib/mysql/ibdata1
---------------C---- 2021-02-20-TEMP/var/lib/mysql/multi-master.info
---------------C---- 2021-02-20-TEMP/var/lib/mysql/mysql_upgrade_info
---------------C---- 2021-02-20-TEMP/var/lib/mysql/mysql
---------------C---- 2021-02-20-TEMP/var/lib/mysql/nextcloud
---------------C---- 2021-02-20-TEMP/var/lib/mysql/performance_schema
---------------C---- 2021-02-20-TEMP/var/lib/mysql/roundcube
---------------C---- 2021-02-20-TEMP/var/lib/mysql/wordpress
---------------C---- 2021-02-20-TEMP/var/lib/mysql/mailserver
---------------C---- 2021-02-20-TEMP/var/lib/mysql/ib_buffer_pool
---------------C---- 2021-02-20-TEMP/var/lib/mysql/tc.log
---------------C---- 2021-02-20-TEMP/var/lib/mysql/ibtmp1

Re: Unexpected "ERROR: clone: did not find source subvol" on btrfs receive

[Andrei Borzenkov]

20.02.2021 20:45, Alexander Wetzel пишет:
> 
> # time btrfs receive -v -f test2 .
> receiving snapshot 2021-02-20-TEMP
> uuid=120113e6-f83c-b240-ba27-259be4c92ea7, ctransid=206769
> parent_uuid=d31d553f-0917-3c48-b65c-ec51fd0c6d89, parent_ctransid=195056
...
> write var/lib/mysql/nextcloud/oc_activity.ibd - offset=737280 length=8192
> ERROR: clone: did not find source subvol

Unforutnately btrfs receive does not print clone source UUID even with
"btrfs receive --dump". The best is to modify process_clone to print
full command including UUID which was not found.

Re: Unexpected "ERROR: clone: did not find source subvol" on btrfs receive

[Alexander Wetzel]

Am 21.02.21 um 07:54 schrieb Andrei Borzenkov:
> 20.02.2021 20:45, Alexander Wetzel пишет:
>>
>> # time btrfs receive -v -f test2 .
>> receiving snapshot 2021-02-20-TEMP
>> uuid=120113e6-f83c-b240-ba27-259be4c92ea7, ctransid=206769
>> parent_uuid=d31d553f-0917-3c48-b65c-ec51fd0c6d89, parent_ctransid=195056
> ...
>> write var/lib/mysql/nextcloud/oc_activity.ibd - offset=737280 length=8192
>> ERROR: clone: did not find source subvol
> 
> Unforutnately btrfs receive does not print clone source UUID even with
> "btrfs receive --dump". The best is to modify process_clone to print
> full command including UUID which was not found.
> 

I've patched cmds/receive.c to print out the uuid subvol_uuid_search was 
not able to find:

Basically these I replaced the original error message with:
uuid_unparse(clone_uuid, uuid_str);
error("clone: did not find source subvol si=%i, uuid=%s", si, uuid_str);

With that modification I get:

At snapshot 2021-02-20-TEMP
ERROR: clone: did not find source subvol si=0, 
uuid=d31d553f-0917-3c48-b65c-ec51fd0c6d89

But uuid d31d553f-0917-3c48-b65c-ec51fd0c6d89 is the uuid of the correct 
parent...

The problem here seems to be the zero return of ubvol_uuid_search().

While compiling I also switched to 
https://github.com/kdave/btrfs-progs.git. Same problem.

I then tracked the error down up to btrfs_uuid_tree_lookup_any():

nr_items is zero after the call
ret = ioctl(fd, BTRFS_IOC_TREE_SEARCH, &search_arg);
(ret is also zero)

So looks like this is a filesystem issue?

Alexander

Re: Unexpected "ERROR: clone: did not find source subvol" on btrfs receive

[Alexander Wetzel]

> While compiling I also switched to 
> https://github.com/kdave/btrfs-progs.git. Same problem.
> 
> I then tracked the error down up to btrfs_uuid_tree_lookup_any():
> 
> nr_items is zero after the call
> ret = ioctl(fd, BTRFS_IOC_TREE_SEARCH, &search_arg);
> (ret is also zero)
> 
> So looks like this is a filesystem issue?

I've now "reused" the ret < 0 output in btrfs_uuid_tree_lookup_any() and 
added nt_items to it, too.

Then I get:

# /home/alex/src/b2/btrfs-progs/btrfs  receive -f test2 .
At snapshot 2021-02-20-TEMP
ioctl(BTRFS_IOC_TREE_SEARCH, uuid, key 483c17093f551dd3, UUID_KEY, 
896d0cfd51ec5cb6, nr_items=0) ret=0, error: No such file or directory
ioctl(BTRFS_IOC_TREE_SEARCH, uuid, key 483c17093f551dd3, UUID_KEY, 
896d0cfd51ec5cb6, nr_items=0) ret=0, error: No such file or directory
ERROR: clone: did not find source subvol si=0, 
uuid=d31d553f-0917-3c48-b65c-ec51fd0c6d89

Any ideas what I can check with that information? The key looks 
interesting...

Here my debug patch against current git:

diff --git a/cmds/receive.c b/cmds/receive.c
index 2aaba3ff..29244f88 100644
--- a/cmds/receive.c
+++ b/cmds/receive.c
@@ -726,6 +726,7 @@ static int process_clone(const char *path, u64 
offset, u64 len,
  	char full_path[PATH_MAX];
  	const char *subvol_path;
  	char full_clone_path[PATH_MAX];
+	char uuid_str[BTRFS_UUID_UNPARSED_SIZE];
  	int clone_fd = -1;

  	ret = path_cat_out(full_path, rctx->full_subvol_path, path);
@@ -750,7 +751,8 @@ static int process_clone(const char *path, u64 
offset, u64 len,
  				ret = -ENOENT;
  			else
  				ret = PTR_ERR(si);
-			error("clone: did not find source subvol");
+			uuid_unparse(clone_uuid, uuid_str);
+			error("clone: did not find source subvol si=%i, uuid=%s", si, uuid_str);
  			goto out;
  		}
  		/* strip the subvolume that we are receiving to from the start of 
subvol_path */
diff --git a/kernel-shared/uuid-tree.c b/kernel-shared/uuid-tree.c
index 21115a4d..82f6d078 100644
--- a/kernel-shared/uuid-tree.c
+++ b/kernel-shared/uuid-tree.c
@@ -64,16 +64,17 @@ static int btrfs_uuid_tree_lookup_any(int fd, const 
u8 *uuid, u8 type,
  	search_arg.key.max_transid = (u64)-1;
  	search_arg.key.nr_items = 1;
  	ret = ioctl(fd, BTRFS_IOC_TREE_SEARCH, &search_arg);
-	if (ret < 0) {
+	if ((ret < 0) || (search_arg.key.nr_items < 1)) {
  		fprintf(stderr,
-			"ioctl(BTRFS_IOC_TREE_SEARCH, uuid, key %016llx, UUID_KEY, %016llx) 
ret=%d, error: %m\n",
+			"ioctl(BTRFS_IOC_TREE_SEARCH, uuid, key %016llx, UUID_KEY, %016llx, 
nr_items=%d) ret=%d, error: %m\n",
  			(unsigned long long)key.objectid,
-			(unsigned long long)key.offset, ret);
+			(unsigned long long)key.offset, search_arg.key.nr_items, ret);
  		ret = -ENOENT;
  		goto out;
  	}

  	if (search_arg.key.nr_items < 1) {
+		fprintf(stderr, "DDD2 ret=%i nr_items=%i\n", ret, 
search_arg.key.nr_items);
  		ret = -ENOENT;
  		goto out;
  	}

Re: Unexpected "ERROR: clone: did not find source subvol" on btrfs receive

[Alexander Wetzel]

Am 21.02.21 um 12:57 schrieb Alexander Wetzel:
>> While compiling I also switched to 
>> https://github.com/kdave/btrfs-progs.git. Same problem.
>>
>> I then tracked the error down up to btrfs_uuid_tree_lookup_any():
>>
>> nr_items is zero after the call
>> ret = ioctl(fd, BTRFS_IOC_TREE_SEARCH, &search_arg);
>> (ret is also zero)
>>
>> So looks like this is a filesystem issue?
> 
> I've now "reused" the ret < 0 output in btrfs_uuid_tree_lookup_any() and 
> added nt_items to it, too.
> 
> Then I get:
> 
> # /home/alex/src/b2/btrfs-progs/btrfs  receive -f test2 .
> At snapshot 2021-02-20-TEMP
> ioctl(BTRFS_IOC_TREE_SEARCH, uuid, key 483c17093f551dd3, UUID_KEY, 
> 896d0cfd51ec5cb6, nr_items=0) ret=0, error: No such file or directory
> ioctl(BTRFS_IOC_TREE_SEARCH, uuid, key 483c17093f551dd3, UUID_KEY, 
> 896d0cfd51ec5cb6, nr_items=0) ret=0, error: No such file or directory
> ERROR: clone: did not find source subvol si=0, 
> uuid=d31d553f-0917-3c48-b65c-ec51fd0c6d89
> 


In common/send-stream.c read_and_process_cmd() the very first time we 
try to use BTRFS_SEND_C_CLONE it triggers the problem on my setup.

Dumping the variables of the problematic call here I get:
   path=var/lib/mysql/nextcloud/oc_activity.ibd
   offset=745472
   len=303104
   uuid=d31d553f-0917-3c48-b65c-ec51fd0c6d89
   clone_ctransid=195056
   clone_path=var/lib/mysql/nextcloud/oc_activity.ibd
   clone_offset=745472

Guessing around I assume this is an instruction to clone 303104 Bytes at 
offset 745472 for var/lib/mysql/nextcloud/oc_activity.ibd from the 
parent subvol uuid d31d553f-0917-3c48-b65c-ec51fd0c6d89 at generation 
195056.

So I suspect now my problem is, that my RO snapshot hs somehow
Generation != (Gen at creation).
A RO snapshot should not be able to get to a newer generation, correct?

Or maybe that btrfs send is using "Gen at creation" instead of 
"Generation"... but don't think so.


# btrfs sub show 2021-02-14/
2021-02-14
         Name:                   2021-02-14
         UUID:                   d31d553f-0917-3c48-b65c-ec51fd0c6d89
         Parent UUID:            a2ff485b-9f8f-2543-ad03-dc7c917e143b
         Received UUID:          -
         Creation time:          2021-02-14 21:46:26 +0100
         Subvolume ID:           358
         Generation:             208977	<---
         Gen at creation:        195056
         Parent ID:              5
         Top level ID:           5
         Flags:                  readonly
         Snapshot(s):
                                 2021-02-20-TEMP

Now I somehow got another test ro snapshot to a new generation:
# btrfs sub snap -r active/ t1
Create a readonly snapshot of 'active/' in './t1'
# btrfs sub show t1
t1
         Name:                   t1
         UUID:                   70e6a915-e03a-fb48-869e-98ab8bad2ad4
         Parent UUID:            a2ff485b-9f8f-2543-ad03-dc7c917e143b
         Received UUID:          -
         Creation time:          2021-02-21 18:02:32 +0100
         Subvolume ID:           411
         Generation:             209009
         Gen at creation:        209009
         Parent ID:              5
         Top level ID:           5
         Flags:                  readonly
         Snapshot(s):


Playing around a bit I found out that renaming a subvol can - but not 
always - advances the generation:

# btrfs sub snap -r active/ t1
Create a readonly snapshot of 'active/' in './t1'
# btrfs sub show t1
t1
         Name:                   t1
         UUID:                   83d278b0-1782-3a4a-8293-c6df2e67acd4
         Parent UUID:            a2ff485b-9f8f-2543-ad03-dc7c917e143b
         Received UUID:          -
         Creation time:          2021-02-21 18:34:40 +0100
         Subvolume ID:           414
         Generation:             209069
         Gen at creation:        209069
         Parent ID:              5
         Top level ID:           5
         Flags:                  readonly
         Snapshot(s):
# mv t1 x1
# btrfs sub show x1
x1
         Name:                   x1
         UUID:                   83d278b0-1782-3a4a-8293-c6df2e67acd4
         Parent UUID:            a2ff485b-9f8f-2543-ad03-dc7c917e143b
         Received UUID:          -
         Creation time:          2021-02-21 18:34:40 +0100
         Subvolume ID:           414
         Generation:             209070
         Gen at creation:        209069
         Parent ID:              5
         Top level ID:           5
         Flags:                  readonly
         Snapshot(s):

But that is not always working. Creating/renaming/deleting snapshots I 
can trigger it from time to time but so far I don't see a pattern.

But then I just got that:
# btrfs sub snap -r active/ q1
Create a readonly snapshot of 'active/' in './q1'
# btrfs sub show q1
q1
         Name:                   q1
         UUID:                   53a3833c-9caa-b944-80d1-8d592c68ff74
         Parent UUID:            a2ff485b-9f8f-2543-ad03-dc7c917e143b
         Received UUID:          -
         Creation time:          2021-02-21 18:40:20 +0100
         Subvolume ID:           416
         Generation:             209084
         Gen at creation:        209083
         Parent ID:              5
         Top level ID:           5
         Flags:                  readonly
         Snapshot(s):
root@mail:/mnt/backup/backupdev#

No rename necessary and the generations also differ...

But I guess I'm at then end of what I can find out without a much better 
understanding of btrfs internals...

I hope someone here can shed more light on that,

Alexander

Re: Unexpected "ERROR: clone: did not find source subvol" on btrfs receive

[Torsten Bronger]

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

Hallöchen!

Alexander Wetzel writes:

> I have a strange problem with btrfs send/receive.  While I can
> create incremental snaphosts but when I try to restore them I
> reproducible get:
>
>> At snapshot 2021-02-20-TEMP
>> ERROR: clone: did not find source subvol

I observe the same thing regularly (but not every time) and logged
it for a couple of weeks, using kernel 5.8.0 (Ubuntu 20.04) for send
and receive, and btrfs-progs v5.4.1.  I use send/receive to sync
large VirtualBox images between my two laptops and a server.

I observed:

- UUID and Receive UUID on both sides match the same way, both if
  its working or if the error occurs.  (I.e., Receive UUID on one
  side matches UUID on the other side, which has no Receive UUID.)

- The “Generation” and “Gen at creation” never match, not amongst
  each other, and not on sending and receiving side.

- I *seem* to suffer no data loss due to it.

I am willing to log further things, or test things.

Regards,
Torsten.

-- 
Torsten Bronger

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 4913 bytes --]