pvesr run: add --verbose flag

We can now pass a $logfunc parameter to replicate() to
produce more verbose logs/output. This is especially useful
for regression testing.

PVE/CLI/pvesr.pm

@@ -33,19 +33,34 @@ __PACKAGE__->register_method ({
 	additionalProperties => 0,
 	properties => {
 	    id => get_standard_option('pve-replication-id', { optional => 1 }),
+	    verbose => {
+		description => "Print more verbose logs to stdout.",
+		type => 'boolean',
+		default => 0,
+		optional => 1,
+	    },
 	},
     },
     returns => { type => 'null' },
     code => sub {
 	my ($param) = @_;
 
+	my $logfunc;
+
+	if ($param->{verbose}) {
+	    $logfunc = sub {
+		my ($start_time, $msg) = @_;
+		print "$msg\n";
+	    };
+	}
+
 	if (my $id = extract_param($param, 'id')) {
 
-	    PVE::Replication::run_single_job($id);
+	    PVE::Replication::run_single_job($id, undef, $logfunc);
 
 	} else {
 
-	    PVE::Replication::run_jobs();
+	    PVE::Replication::run_jobs(undef, $logfunc);
 	}
 
 	return undef;

PVE/Replication.pm

@@ -156,14 +156,15 @@ my $get_next_job = sub {
     return $jobcfg;
 };
 
+
 sub replicate {
-    my ($jobcfg, $start_time) = @_;
+    my ($jobcfg, $start_time, $logfunc) = @_;
 
     die "implement me";
 }
 
 my $run_replication = sub {
-    my ($stateobj, $jobcfg, $start_time) = @_;
+    my ($stateobj, $jobcfg, $start_time, $logfunc) = @_;
 
     my $state = delete $jobcfg->{state};
 
@@ -183,7 +184,9 @@ my $run_replication = sub {
     $state->{last_try} = $start_time;
     $update_job_state->($stateobj, $jobcfg,  $state);
 
-    eval { replicate($jobcfg, $start_time); };
+    $logfunc->($start_time, "$jobcfg->{id}: start replication job") if $logfunc;
+
+    eval { replicate($jobcfg, $start_time, $logfunc); };
     my $err = $@;
 
     $state->{duration} = tv_interval($t0);
@@ -194,8 +197,14 @@ my $run_replication = sub {
 	$state->{fail_count}++;
 	$state->{error} = "$err";
 	$update_job_state->($stateobj, $jobcfg,  $state);
-	warn $err;
-   } else {
+	if ($logfunc) {
+	    chomp $err;
+	    $logfunc->($start_time, "$jobcfg->{id}: end replication job with error: $err");
+	} else {
+	    warn $err;
+	}
+    } else {
+	$logfunc->($start_time, "$jobcfg->{id}: end replication job") if $logfunc;
 	$state->{last_sync} = $start_time;
 	$state->{fail_count} = 0;
 	delete $state->{error};
@@ -204,7 +213,7 @@ my $run_replication = sub {
 };
 
 sub run_single_job {
-    my ($jobid, $now) = @_; # passing $now useful for regression testing
+    my ($jobid, $now, $logfunc) = @_; # passing $now useful for regression testing
 
     my $local_node = PVE::INotify::nodename();
 
@@ -239,7 +248,7 @@ sub run_single_job {
 	$jobcfg->{state}->{last_iteration} = $now;
 	$update_job_state->($stateobj, $jobcfg,  $jobcfg->{state});
 
-	$run_replication->($stateobj, $jobcfg, $now);
+	$run_replication->($stateobj, $jobcfg, $now, $logfunc);
     };
 
     my $res = PVE::Tools::lock_file($state_path, 60, $code);
@@ -247,7 +256,7 @@ sub run_single_job {
 }
 
 sub run_jobs {
-    my ($now) = @_; # passing $now useful for regression testing
+    my ($now, $logfunc) = @_; # useful for regression testing
 
     my $iteration = $now // time();
 
@@ -256,7 +265,7 @@ sub run_jobs {
 	my $start_time = $now // time();
 
 	while (my $jobcfg = $get_next_job->($stateobj, $iteration, $start_time)) {
-	    $run_replication->($stateobj, $jobcfg, $start_time);
+	    $run_replication->($stateobj, $jobcfg, $start_time, $logfunc);
 	    $start_time = $now // time();
 	}
     };

bin/test/ReplicationTestEnv.pm

@@ -215,7 +215,7 @@ sub track_jobs {
 	}
     }
 
-    PVE::Replication::run_jobs($ctime);
+    PVE::Replication::run_jobs($ctime, \&logmsg);
 
     my $new = PVE::Replication::job_status();
 

bin/test/replication_test4.log

@@ -1,7 +1,13 @@
 1000 job_900_to_node2: new job next_sync => 900
+1000 job_900_to_node2: start replication job
+1000 job_900_to_node2: end replication job with error: faked replication error
 1000 job_900_to_node2: changed config next_sync => 1300
 1000 job_900_to_node2: changed state last_try => 1000, fail_count => 1, error => faked replication error
+1300 job_900_to_node2: start replication job
+1300 job_900_to_node2: end replication job with error: faked replication error
 1300 job_900_to_node2: changed config next_sync => 1900
 1300 job_900_to_node2: changed state last_try => 1300, fail_count => 2
+1900 job_900_to_node2: start replication job
+1900 job_900_to_node2: end replication job with error: faked replication error
 1900 job_900_to_node2: changed config next_sync => 0
 1900 job_900_to_node2: changed state last_try => 1900, fail_count => 3