[PATCH common v2 1/2] cmd: run: do not cancel the caller's alarm

[Kefu Chai <k.chai@proxmox.com>]

run() calls alarm(0) when done, so a caller's pending alarm is lost,
or pushed back if run had a timeout of its own. The cfs lock relies on
such an alarm: on shared LVM, 'vgs' and 'lvcreate' run under the
storage lock, and after 'vgs' nothing limits 'lvcreate' anymore.

Only touch the alarm if run has its own timeout, and afterwards give
the caller's alarm back what is left of it.

Disable the caller's alarm before installing our own handler: between
installing it and arming our timeout, the caller's alarm could fire
into the new handler and be reported as run's own timeout.

The caller's alarm stays armed while run has no timeout of its own, so
it can interrupt the flush of the last buffered stderr line. Catch an
error from that flush instead of letting it replace the error run
already collected: warn it on a timeout, append it otherwise.

Signed-off-by: Kefu Chai <k.chai@proxmox.com>
---
 src/PVE/Cmd.pm   | 32 +++++++++++++++++++++++++++-----
 test/cmd-test.pl | 45 +++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 72 insertions(+), 5 deletions(-)

diff --git a/src/PVE/Cmd.pm b/src/PVE/Cmd.pm
index 27c9193..4b470a1 100644
--- a/src/PVE/Cmd.pm
+++ b/src/PVE/Cmd.pm
@@ -100,6 +100,7 @@ sub run($cmd, %param) {
     my $laststderr;
     my $timeout;
     my $oldtimeout;
+    my $armed_at;
     my $pid;
     my $exitcode = -1;
 
@@ -193,9 +194,15 @@ sub run($cmd, %param) {
 
         die $err if $err;
 
+        # disable the caller's alarm before installing our own handler, so
+        # the caller's alarm cannot fire into it and be reported as ours
+        if ($timeout) {
+            $oldtimeout = alarm(0);
+            $armed_at = Time::HiRes::time();
+        }
         local $SIG{ALRM} = sub { die "got timeout\n"; }
             if $timeout;
-        $oldtimeout = alarm($timeout) if $timeout;
+        alarm($timeout) if $timeout;
 
         &$afterfork() if $afterfork;
 
@@ -295,20 +302,35 @@ sub run($cmd, %param) {
             }
         }
 
-        alarm(0);
+        alarm(0) if $timeout; # while our handler is still in place
     };
 
     my $err = $@;
 
-    alarm(0);
+    alarm(0) if $armed_at;
 
     if ($errmsg && $laststderr) {
-        &$errfunc(undef); # flush laststderr
+        # the caller's alarm can fire during the flush, and the callback can
+        # die on its own, so do not let it replace the error we already have
+        my $flush_error;
+        eval { &$errfunc(undef) }; # flush laststderr
+        $flush_error = $@;
+        if (length($flush_error)) {
+            if ($err eq "got timeout\n") {
+                warn $flush_error;
+            } else {
+                $err = "$flush_error\n$err";
+            }
+        }
     }
 
     umask($old_umask) if defined($old_umask);
 
-    alarm($oldtimeout) if $oldtimeout;
+    # give the caller's alarm back what is left of it, a lock may depend on it
+    if ($oldtimeout) {
+        my $left = $oldtimeout - (Time::HiRes::time() - $armed_at);
+        alarm($left > 0 ? $left : 0.001);
+    }
 
     if ($err) {
         if ($pid && ($err eq "got timeout\n")) {
diff --git a/test/cmd-test.pl b/test/cmd-test.pl
index c2f7ae7..518b369 100755
--- a/test/cmd-test.pl
+++ b/test/cmd-test.pl
@@ -11,6 +11,7 @@ use lib '../src';
 use PVE::Cmd;
 
 use Test::More;
+use Time::HiRes ();
 
 # shell_quote: quote a single argument for the shell
 #
@@ -67,6 +68,50 @@ ok($@, 'run dies on a failing command without noerr');
 
 is(PVE::Cmd::run_command(['true']), 0, 'run_command works as a wrapper for run');
 
+# run must leave a pending alarm of its caller alone, like the time limit of a lock
+#
+# name  - how run is called
+# cmd   - command to run, sleeps for a second by default
+# param - parameters for run
+my $caller_alarm_tests = [
+    { name => 'without a timeout', param => {} },
+    { name => 'with a timeout', param => { timeout => 5 } },
+    {
+        name => 'with a timeout on a command that cannot start',
+        cmd => ['/nonexistent/command'],
+        param => { timeout => 5 },
+    },
+];
+for my $test ($caller_alarm_tests->@*) {
+    my $fired;
+    local $SIG{ALRM} = sub { $fired = Time::HiRes::time() };
+    my $start = Time::HiRes::time();
+    Time::HiRes::alarm(2);
+    eval { PVE::Cmd::run($test->{cmd} // ['sleep', '1'], $test->{param}->%*) };
+    Time::HiRes::sleep(0.1) until $fired || Time::HiRes::time() - $start > 5;
+    Time::HiRes::alarm(0);
+    ok($fired, "the caller's alarm still fires after run $test->{name}");
+    my $after = defined($fired) ? $fired - $start : 99;
+    cmp_ok($after, '<', 2.5, "run $test->{name} does not delay the caller's alarm");
+}
+
+# the flush of the last buffered stderr line must not replace the error that
+# made run stop, even if the errfunc dies on it
+{
+    my @warned;
+    local $SIG{__WARN__} = sub { push @warned, @_ };
+    eval {
+        PVE::Cmd::run(
+            ['sh', '-c', 'echo boomtrigger >&2; sleep 5'],
+            timeout => 1,
+            errmsg => 'msg',
+            errfunc => sub { die "boom\n" if defined($_[0]) && $_[0] =~ /boomtrigger/ },
+        );
+    };
+    like($@, qr/got timeout/, 'run reports its timeout, not a dying errfunc');
+    like(join('', @warned), qr/boom/, 'run warns about the dying errfunc');
+}
+
 # TODO:
 # - cover pipe_socket (needs a socket peer)
 # - cover timeouts and the errfunc/logfunc callbacks
-- 
2.47.3