[pve-devel] [PATCH v2 storage] fix #3004: show progress of offline migration in task log

[Fiona Ebner]

Sorry about the late review!

Am 16.11.22 um 12:02 schrieb Leo Nunner:
> --- a/PVE/Storage.pm
> +++ b/PVE/Storage.pm

Needs a rebase, because files got moved to src/

> @@ -821,12 +821,25 @@ sub storage_migrate {
>  
>      my $new_volid;
>      my $pattern = volume_imported_message(undef, 1);
> -    my $match_volid_and_log = sub {
> +    # Matches new volid and rate-limits dd output
> +    my $match_and_log = sub {

Why rename the function?

>  	my $line = shift;
> +	my $show = 1;
> +
> +	# rate-limit dd logs
> +	if ($line =~ /(?:\d+ bytes)(?:.+?copied, )(\d+) s/) {
> +	    if ($1 < 60) { # if < 60s, print every 3s
> +		$show = !($1 % 3);
> +	    } elsif($1 < 600) { # if < 10mins, print every 10s

Style nit: missing space after elsif

> +		$show = !($1 % 10);
> +	    } else { # else, print every 30s
> +		$show = !($1 % 30);
> +	    }
> +	}

Upon completion something strange happens: There's a duplicate final log
with fractional seconds and duplicate records in/out.

> 2023-08-30 09:57:05 Formatting '/mnt/pve/dir/images/105/vm-105-disk-0.raw', fmt=raw size=1073741824 preallocation=off
> 2023-08-30 09:57:08 1050218496 bytes (1.1 GB, 1002 MiB) copied, 3 s, 350 MB/s
> 2023-08-30 09:57:08 262144+0 records in
> 2023-08-30 09:57:08 262144+0 records out
> 2023-08-30 09:57:08 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 3.06228 s, 351 MB/s
> 2023-08-30 09:57:08 10458+11861 records in
> 2023-08-30 09:57:08 10458+11861 records out
> 2023-08-30 09:57:08 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 2.75082 s, 390 MB/s
> 2023-08-30 09:57:08 successfully imported 'dir:105/vm-105-disk-0.raw'

> 2023-08-30 10:00:38   Logical volume "vm-105-disk-0" created.
> 2023-08-30 10:00:42 873070592 bytes (873 MB, 833 MiB) copied, 3 s, 291 MB/s
> 2023-08-30 10:00:45 1944322048 bytes (1.9 GB, 1.8 GiB) copied, 6 s, 324 MB/s
> 2023-08-30 10:00:48 2976448512 bytes (3.0 GB, 2.8 GiB) copied, 9 s, 331 MB/s
> 2023-08-30 10:00:51 3998810112 bytes (4.0 GB, 3.7 GiB) copied, 12 s, 333 MB/s
> 2023-08-30 10:00:51 65536+0 records in
> 2023-08-30 10:00:51 65536+0 records out
> 2023-08-30 10:00:51 4294967296 bytes (4.3 GB, 4.0 GiB) copied, 13.1171 s, 327 MB/s
> 2023-08-30 10:00:53 44465+42142 records in
> 2023-08-30 10:00:53 44465+42142 records out
> 2023-08-30 10:00:53 4294967296 bytes (4.3 GB, 4.0 GiB) copied, 14.4084 s, 298 MB/s
> 2023-08-30 10:00:53 successfully imported 'lvmthin:vm-105-disk-0'
I think it's because we get it once from the source and once from the
target as better seen when using insecure migration:

> 2023-08-30 10:10:07 262144+0 records in
> 2023-08-30 10:10:07 262144+0 records out
> 2023-08-30 10:10:07 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 1.43834 s, 747 MB/s
> 2023-08-30 10:10:07 [pve8a2] Formatting '/mnt/pve/dir/images/105/vm-105-disk-0.raw', fmt=raw size=1073741824 preallocation=off
> 2023-08-30 10:10:07 [pve8a2] 6997+25632 records in
> 2023-08-30 10:10:07 [pve8a2] 6997+25632 records out
> 2023-08-30 10:10:07 [pve8a2] 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 1.41876 s, 757 MB/s
> 2023-08-30 10:10:07 [pve8a2] successfully imported 'dir:105/vm-105-disk-0.raw'
> 2023-08-30 10:10:07 volume 'dir:105/vm-105-disk-0.raw' is 'dir:105/vm-105-disk-0.raw' on the target

For insecure migration, we know which logs originate from source and
which from the target, so we could avoid the confusing duplicates. Maybe
there is a not too-involved way for secure migration too?