[PATCH ha-manager 0/7] some test logging output improvements

[PATCH ha-manager 0/7] some test logging output improvements

[Daniel Kral]

This patch series makes some improvements on how tests output their
logs, especially to make any unexpected warnings fail the test cases.
This catches the typical 'uninitialized variable used' and other Perl
warnings, which would have gone unnoticed beforehand as there's much
more output on STDOUT than STDERR.

This is a small QoL improvement when working on the HA stack because it
catches newly introduced perl warnings early and a

    git rebase master --exec 'make clean && make deb'

with enough test branch coverage should give at least some confidence
that the individual patches are ordered correctly and do not introduce
Perl warnings.

Also a small patch at the end I've used locally for some time to better
highlight the diff output for failed test cases.



Daniel Kral (7):
  sim: always limit the priority level to 4 characters
  consistently use correct priority levels for log calls
  sim: hardware: factor common service lock hash access in
    unlock_service
  use log with warning priority instead of warn where possible
  pve-ha-tester: capture and fail for unexpected perl warnings
  test: ha-tester: use consistent word casing for failed test messages
  test: ha-tester: use colorized diff for unexpected test log outputs

 src/PVE/HA/Env.pm                        |  2 ++
 src/PVE/HA/Env/PVE2.pm                   |  4 ++--
 src/PVE/HA/Fence.pm                      |  2 +-
 src/PVE/HA/Manager.pm                    |  6 +++---
 src/PVE/HA/Resources/PVEVM.pm            |  2 +-
 src/PVE/HA/Sim/Env.pm                    |  2 ++
 src/PVE/HA/Sim/Hardware.pm               | 17 ++++++++++-------
 src/PVE/HA/Sim/RTEnv.pm                  |  1 +
 src/PVE/HA/Sim/RTHardware.pm             |  1 +
 src/PVE/HA/Sim/Resources/VirtCT.pm       |  2 +-
 src/PVE/HA/Sim/TestHardware.pm           |  1 +
 src/pve-ha-tester                        |  8 ++++++++
 src/test/ha-tester.pl                    |  6 +++---
 src/test/test-locked-service2/log.expect |  9 +++++++++
 14 files changed, 45 insertions(+), 18 deletions(-)

-- 
2.47.3

[PATCH ha-manager 1/7] sim: always limit the priority level to 4 characters

[Daniel Kral]

This is already done in the PVE::HA::Sim::TestEnv::log(), do the same
for the other Sim Env/Hardware implementations as any longer priority
level (such as 'warning') would produce a log line, where the priority
level would misalign the following time, log id and message columns.

Signed-off-by: Daniel Kral <d.kral@proxmox.com>
---
 src/PVE/HA/Sim/Env.pm          | 1 +
 src/PVE/HA/Sim/Hardware.pm     | 1 +
 src/PVE/HA/Sim/RTEnv.pm        | 1 +
 src/PVE/HA/Sim/RTHardware.pm   | 1 +
 src/PVE/HA/Sim/TestHardware.pm | 1 +
 5 files changed, 5 insertions(+)

diff --git a/src/PVE/HA/Sim/Env.pm b/src/PVE/HA/Sim/Env.pm
index 65d4efad..63368117 100644
--- a/src/PVE/HA/Sim/Env.pm
+++ b/src/PVE/HA/Sim/Env.pm
@@ -332,6 +332,7 @@ sub log {
     chomp $msg;
 
     my $time = $self->get_time();
+    $level = substr($level, 0, 4);
 
     printf("%-5s %5d %12s: $msg\n", $level, $time, "$self->{nodename}/$self->{log_id}");
 }
diff --git a/src/PVE/HA/Sim/Hardware.pm b/src/PVE/HA/Sim/Hardware.pm
index 82f85c97..163e35af 100644
--- a/src/PVE/HA/Sim/Hardware.pm
+++ b/src/PVE/HA/Sim/Hardware.pm
@@ -669,6 +669,7 @@ sub log {
     chomp $msg;
 
     my $time = $self->get_time();
+    $level = substr($level, 0, 4);
 
     $id = 'hardware' if !$id;
 
diff --git a/src/PVE/HA/Sim/RTEnv.pm b/src/PVE/HA/Sim/RTEnv.pm
index ab5ac996..50d0731e 100644
--- a/src/PVE/HA/Sim/RTEnv.pm
+++ b/src/PVE/HA/Sim/RTEnv.pm
@@ -31,6 +31,7 @@ sub log {
     my ($self, $level, $msg) = @_;
 
     chomp $msg;
+    $level = substr($level, 0, 4);
 
     my $time = $self->get_time();
 
diff --git a/src/PVE/HA/Sim/RTHardware.pm b/src/PVE/HA/Sim/RTHardware.pm
index 9528f542..d16582a3 100644
--- a/src/PVE/HA/Sim/RTHardware.pm
+++ b/src/PVE/HA/Sim/RTHardware.pm
@@ -65,6 +65,7 @@ sub log {
     chomp $msg;
 
     my $time = $self->get_time();
+    $level = substr($level, 0, 4);
 
     $id = 'hardware' if !$id;
 
diff --git a/src/PVE/HA/Sim/TestHardware.pm b/src/PVE/HA/Sim/TestHardware.pm
index ebe6b546..0cedce7b 100644
--- a/src/PVE/HA/Sim/TestHardware.pm
+++ b/src/PVE/HA/Sim/TestHardware.pm
@@ -68,6 +68,7 @@ sub log {
     chomp $msg;
 
     my $time = $self->get_time();
+    $level = substr($level, 0, 4);
 
     $id = 'hardware' if !$id;
 
-- 
2.47.3

[PATCH ha-manager 2/7] consistently use correct priority levels for log calls

[Daniel Kral]

The correct priority string for warnings is 'warning' and for errors is
'err' as this is relayed directly to the PVE::SafeSyslog::syslog() in
the PVE::HA::Env::PVE2::log() implementation.

This doesn't change the test log output as its log() implementation
trims the priority level to the first four characters.

This doesn't have any functional changes, because PVE::SafeSyslog
already handles the 'warn' string correctly and the log calls with
'error' are only for tests, but it's better to be consistent here.

Signed-off-by: Daniel Kral <d.kral@proxmox.com>
---
 src/PVE/HA/Env.pm                  | 2 ++
 src/PVE/HA/Env/PVE2.pm             | 2 +-
 src/PVE/HA/Fence.pm                | 2 +-
 src/PVE/HA/Manager.pm              | 6 +++---
 src/PVE/HA/Sim/Env.pm              | 1 +
 src/PVE/HA/Sim/Hardware.pm         | 8 ++++----
 src/PVE/HA/Sim/Resources/VirtCT.pm | 2 +-
 7 files changed, 13 insertions(+), 10 deletions(-)

diff --git a/src/PVE/HA/Env.pm b/src/PVE/HA/Env.pm
index 44c26854..cd31de73 100644
--- a/src/PVE/HA/Env.pm
+++ b/src/PVE/HA/Env.pm
@@ -169,6 +169,8 @@ sub get_node_info {
     return $self->{plug}->get_node_info();
 }
 
+# $level must match a valid value as the priority levels in Sys::Syslog, which are:
+# 'emerg', 'alert', 'crit', 'err', 'warning', 'notice', 'info', and 'debug'.
 sub log {
     my ($self, $level, @args) = @_;
 
diff --git a/src/PVE/HA/Env/PVE2.pm b/src/PVE/HA/Env/PVE2.pm
index 3caf32fc..68bbe8d2 100644
--- a/src/PVE/HA/Env/PVE2.pm
+++ b/src/PVE/HA/Env/PVE2.pm
@@ -447,7 +447,7 @@ sub cluster_state_update {
 
     eval { PVE::Cluster::cfs_update(1) };
     if (my $err = $@) {
-        $self->log('warn', "cluster file system update failed - $err");
+        $self->log('warning', "cluster file system update failed - $err");
         return 0;
     }
 
diff --git a/src/PVE/HA/Fence.pm b/src/PVE/HA/Fence.pm
index 49d673f4..84d86794 100644
--- a/src/PVE/HA/Fence.pm
+++ b/src/PVE/HA/Fence.pm
@@ -191,7 +191,7 @@ sub process_fencing {
             $tried_device_count++; # try next available device
             return if run_fence_jobs($node, $tried_device_count);
 
-            $haenv->log('warn', "could not start fence job at try '$tried_device_count'");
+            $haenv->log('warning', "could not start fence job at try '$tried_device_count'");
         }
 
         $results->{$node}->{failure} = 1;
diff --git a/src/PVE/HA/Manager.pm b/src/PVE/HA/Manager.pm
index b69a6bba..5ebf9caa 100644
--- a/src/PVE/HA/Manager.pm
+++ b/src/PVE/HA/Manager.pm
@@ -682,7 +682,7 @@ sub update_crm_commands {
             my $state = $ns->get_node_state($node);
             if ($ms->{disarm}) {
                 $haenv->log(
-                    'warn',
+                    'warning',
                     "ignoring maintenance command for node $node - HA stack is disarmed",
                 );
             } elsif ($state eq 'online') {
@@ -701,7 +701,7 @@ sub update_crm_commands {
             my $state = $ns->get_node_state($node);
             if ($state ne 'maintenance') {
                 $haenv->log(
-                    'warn',
+                    'warning',
                     "clearing maintenance of node $node requested, but it's in state $state",
                 );
             }
@@ -906,7 +906,7 @@ sub handle_disarm {
     for my $sid (sort keys %$ss) {
         my $state = $ss->{$sid}->{state};
         if ($state eq 'fence' || $state eq 'recovery') {
-            $haenv->log('warn', "deferring disarm - service '$sid' is in '$state' state");
+            $haenv->log('warning', "deferring disarm - service '$sid' is in '$state' state");
             $deferred_sids->{$sid} = 1;
         } elsif ($state eq 'migrate' || $state eq 'relocate') {
             $haenv->log('info', "deferring disarm - service '$sid' is in '$state' state");
diff --git a/src/PVE/HA/Sim/Env.pm b/src/PVE/HA/Sim/Env.pm
index 63368117..38ac1d03 100644
--- a/src/PVE/HA/Sim/Env.pm
+++ b/src/PVE/HA/Sim/Env.pm
@@ -348,6 +348,7 @@ sub send_notification {
     $subject = $subject =~ s/\{\{fence-status}}/$properties->{"fence-status"}/r;
 
     # only log subject, do not spam the logs
+    # allow invalid 'email' priority level here as it's only for test log output
     $self->log('email', $subject);
 }
 
diff --git a/src/PVE/HA/Sim/Hardware.pm b/src/PVE/HA/Sim/Hardware.pm
index 163e35af..891d552f 100644
--- a/src/PVE/HA/Sim/Hardware.pm
+++ b/src/PVE/HA/Sim/Hardware.pm
@@ -455,7 +455,7 @@ sub read_static_service_stats {
 
     my $filename = "$self->{statusdir}/static_service_stats";
     my $stats = eval { PVE::HA::Tools::read_json_from_file($filename) };
-    $self->log('error', "loading static service stats failed - $@") if $@;
+    $self->log('err', "loading static service stats failed - $@") if $@;
 
     return $stats;
 }
@@ -465,7 +465,7 @@ sub read_dynamic_service_stats {
 
     my $filename = "$self->{statusdir}/dynamic_service_stats";
     my $stats = eval { PVE::HA::Tools::read_json_from_file($filename) };
-    $self->log('error', "loading dynamic service stats failed - $@") if $@;
+    $self->log('err', "loading dynamic service stats failed - $@") if $@;
 
     return $stats;
 }
@@ -475,7 +475,7 @@ sub write_static_service_stats {
 
     my $filename = "$self->{statusdir}/static_service_stats";
     eval { PVE::HA::Tools::write_json_to_file($filename, $stats) };
-    $self->log('error', "writing static service stats failed - $@") if $@;
+    $self->log('err', "writing static service stats failed - $@") if $@;
 }
 
 sub write_dynamic_service_stats {
@@ -483,7 +483,7 @@ sub write_dynamic_service_stats {
 
     my $filename = "$self->{statusdir}/dynamic_service_stats";
     eval { PVE::HA::Tools::write_json_to_file($filename, $stats) };
-    $self->log('error', "writing dynamic service stats failed - $@") if $@;
+    $self->log('err', "writing dynamic service stats failed - $@") if $@;
 }
 
 sub new {
diff --git a/src/PVE/HA/Sim/Resources/VirtCT.pm b/src/PVE/HA/Sim/Resources/VirtCT.pm
index 594dba56..3f6df85e 100644
--- a/src/PVE/HA/Sim/Resources/VirtCT.pm
+++ b/src/PVE/HA/Sim/Resources/VirtCT.pm
@@ -25,7 +25,7 @@ sub migrate {
     my $ss = $hardware->read_service_status($nodename);
 
     if ($online && $ss->{$sid}) {
-        $haenv->log('warn', "unable to live migrate running container, fallback to relocate");
+        $haenv->log('warning', "unable to live migrate running container, fallback to relocate");
         $online = 0;
     }
 
-- 
2.47.3

[PATCH ha-manager 3/7] sim: hardware: factor common service lock hash access in unlock_service

[Daniel Kral]

Signed-off-by: Daniel Kral <d.kral@proxmox.com>
---
 src/PVE/HA/Sim/Hardware.pm | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/src/PVE/HA/Sim/Hardware.pm b/src/PVE/HA/Sim/Hardware.pm
index 891d552f..88fd64e8 100644
--- a/src/PVE/HA/Sim/Hardware.pm
+++ b/src/PVE/HA/Sim/Hardware.pm
@@ -319,12 +319,14 @@ sub unlock_service {
 
     die "no such service '$sid'\n" if !$conf->{$sid};
 
-    if (!defined($conf->{$sid}->{lock})) {
+    my $service_lock = $conf->{$sid}->{lock};
+
+    if (!defined($service_lock)) {
         return undef;
     }
 
-    if (defined($lock) && $conf->{$sid}->{lock} ne $lock) {
-        warn "found lock '$conf->{$sid}->{lock}' trying to remove '$lock' lock\n";
+    if (defined($lock) && $service_lock ne $lock) {
+        warn "found lock '$service_lock' trying to remove '$lock' lock\n";
         return undef;
     }
 
-- 
2.47.3

[PATCH ha-manager 4/7] use log with warning priority instead of warn where possible

[Daniel Kral]

The HA Manager should relay all output through its PVE::HA::Env::log()
interface to allow consistent output.

In the case for PVE::HA::Sim::Hardware::unlock_service(), the
test-locked-service2 integration test didn't capture the expected
behavior in its expected log output.

Signed-off-by: Daniel Kral <d.kral@proxmox.com>
---
 src/PVE/HA/Env/PVE2.pm                   | 2 +-
 src/PVE/HA/Resources/PVEVM.pm            | 2 +-
 src/PVE/HA/Sim/Hardware.pm               | 2 +-
 src/test/test-locked-service2/log.expect | 9 +++++++++
 4 files changed, 12 insertions(+), 3 deletions(-)

diff --git a/src/PVE/HA/Env/PVE2.pm b/src/PVE/HA/Env/PVE2.pm
index 68bbe8d2..782d19db 100644
--- a/src/PVE/HA/Env/PVE2.pm
+++ b/src/PVE/HA/Env/PVE2.pm
@@ -439,7 +439,7 @@ sub loop_end_hook {
 
     my $delay = $self->get_time() - $self->{loop_start};
 
-    warn "loop took too long ($delay seconds)\n" if $delay > 30;
+    $self->log('warning', "loop took too long ($delay seconds)") if $delay > 30;
 }
 
 sub cluster_state_update {
diff --git a/src/PVE/HA/Resources/PVEVM.pm b/src/PVE/HA/Resources/PVEVM.pm
index 1621c15b..dceb08e3 100644
--- a/src/PVE/HA/Resources/PVEVM.pm
+++ b/src/PVE/HA/Resources/PVEVM.pm
@@ -146,7 +146,7 @@ sub check_running {
         my $conf = PVE::QemuConfig->load_config($vmid, $nodename);
         if (defined($conf->{lock}) && $conf->{lock} eq 'backup') {
             my $qmpstatus = eval { PVE::QemuServer::Monitor::mon_cmd($vmid, 'query-status') };
-            warn "$@\n" if $@;
+            $haenv->log('warning', "$@") if $@;
 
             return 0 if defined($qmpstatus) && $qmpstatus->{status} eq 'prelaunch';
         }
diff --git a/src/PVE/HA/Sim/Hardware.pm b/src/PVE/HA/Sim/Hardware.pm
index 88fd64e8..4ebe2adf 100644
--- a/src/PVE/HA/Sim/Hardware.pm
+++ b/src/PVE/HA/Sim/Hardware.pm
@@ -326,7 +326,7 @@ sub unlock_service {
     }
 
     if (defined($lock) && $service_lock ne $lock) {
-        warn "found lock '$service_lock' trying to remove '$lock' lock\n";
+        $self->log('warning', "found lock '$service_lock' trying to remove '$lock' lock");
         return undef;
     }
 
diff --git a/src/test/test-locked-service2/log.expect b/src/test/test-locked-service2/log.expect
index bfdc8ab0..a932f14b 100644
--- a/src/test/test-locked-service2/log.expect
+++ b/src/test/test-locked-service2/log.expect
@@ -39,6 +39,15 @@ info    340    node1/crm: node 'node3': state changed from 'fence' => 'unknown'
 emai    340    node1/crm: SUCCEED: fencing: acknowledged - got agent lock for node 'node3'
 info    340    node1/crm: service 'vm:103': state changed from 'fence' to 'recovery'
 info    340    node1/crm: recover service 'vm:103' from fenced node 'node3' to node 'node1'
+warn    340     hardware: found lock 'create' trying to remove 'backup' lock
+warn    340     hardware: found lock 'create' trying to remove 'mounted' lock
+warn    340     hardware: found lock 'create' trying to remove 'migrate' lock
+warn    340     hardware: found lock 'create' trying to remove 'clone' lock
+warn    340     hardware: found lock 'create' trying to remove 'rollback' lock
+warn    340     hardware: found lock 'create' trying to remove 'snapshot' lock
+warn    340     hardware: found lock 'create' trying to remove 'snapshot-delete' lock
+warn    340     hardware: found lock 'create' trying to remove 'suspending' lock
+warn    340     hardware: found lock 'create' trying to remove 'suspended' lock
 info    340    node1/crm: service 'vm:103': state changed from 'recovery' to 'started'  (node = node1)
 info    341    node1/lrm: got lock 'ha_agent_node1_lock'
 info    341    node1/lrm: status change wait_for_agent_lock => active
-- 
2.47.3

[PATCH ha-manager 5/7] pve-ha-tester: capture and fail for unexpected perl warnings

[Daniel Kral]

Make any HA integration tests fail, which output some unexpected
warning.

This assumes that the HA stack's code always uses the
PVE::HA::Env::log() interface to output any relevant information for
users and the test cases.

This catches any uninitialized values in the test cases early in the
build/test process, which would have gone unnoticed before as these
weren't considered failed tests.

Signed-off-by: Daniel Kral <d.kral@proxmox.com>
---
 src/pve-ha-tester | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/src/pve-ha-tester b/src/pve-ha-tester
index b7dc4d66..5f13b460 100755
--- a/src/pve-ha-tester
+++ b/src/pve-ha-tester
@@ -19,6 +19,14 @@ sub show_usage {
 my $testdir = shift || show_usage();
 my $hardware = PVE::HA::Sim::TestHardware->new($testdir);
 
+$SIG{'__WARN__'} = sub {
+    my $err = $@;
+    my $message = $_[0];
+    chomp $message;
+    $hardware->log('warn', $message, 'perl');
+    $@ = $err;
+};
+
 $hardware->log('info', "starting simulation");
 
 eval { $hardware->run(); };
-- 
2.47.3

[PATCH ha-manager 6/7] test: ha-tester: use consistent word casing for failed test messages

[Daniel Kral]

The early return above for a non-zero return value from system() for the
execution of 'pve-ha-tester' uses an uppercase 'Test', so do it for the
others as well.

Signed-off-by: Daniel Kral <d.kral@proxmox.com>
---
 src/test/ha-tester.pl | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/test/ha-tester.pl b/src/test/ha-tester.pl
index 9fab15c3..34f5ef1c 100755
--- a/src/test/ha-tester.pl
+++ b/src/test/ha-tester.pl
@@ -48,10 +48,10 @@ sub do_run_test {
     if (-f $logexpect) {
         my $cmd = ['diff', '-u', $logexpect, $logfile];
         $res = system(@$cmd);
-        return "test '$dir' failed\n" if $res != 0;
+        return "Test '$dir' failed\n" if $res != 0;
     } else {
         $res = system('cp', $logfile, $logexpect);
-        return "test '$dir' failed\n" if $res != 0;
+        return "Test '$dir' failed\n" if $res != 0;
     }
     print "end: $dir (success)\n";
 
-- 
2.47.3

[PATCH ha-manager 7/7] test: ha-tester: use colorized diff for unexpected test log outputs

[Daniel Kral]

Make the diffs for failed integration tests use color, which makes it a
little easier to read on terminals with color support.

diff's --color defaults to --color='auto', which makes sure that diff
does only output the relevant ANSI escape codes for ttys.

Signed-off-by: Daniel Kral <d.kral@proxmox.com>
---
 src/test/ha-tester.pl | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/test/ha-tester.pl b/src/test/ha-tester.pl
index 34f5ef1c..71aa59e3 100755
--- a/src/test/ha-tester.pl
+++ b/src/test/ha-tester.pl
@@ -46,7 +46,7 @@ sub do_run_test {
     my $logexpect = "$dir/log.expect";
 
     if (-f $logexpect) {
-        my $cmd = ['diff', '-u', $logexpect, $logfile];
+        my $cmd = ['diff', '--color', '-u', $logexpect, $logfile];
         $res = system(@$cmd);
         return "Test '$dir' failed\n" if $res != 0;
     } else {
-- 
2.47.3