[PATCH common 0/2] cmd: run: do not leave the command behind on a caller's timeout

[PATCH common 0/2] cmd: run: do not leave the command behind on a caller's timeout

[Kefu Chai]

Hi,

a colleague ran 'pvesm alloc' on an RBD pool whose placement groups
never became active. After 60 seconds the storage lock gave up and got
released, but 'rbd create' just kept running. As far as I can tell,
the lock's alarm handler dies inside run(), and run() only kills its
command on its own timeout or when a callback dies.

Patch 2 kills and reaps the command after run's eval if it's still
around. While looking into this I also noticed that run() cancels the
caller's alarm when it's done, so on shared LVM 'lvcreate' can run
without the lock's limit once 'vgs' ran before it. Patch 1 tries to
fix that.

My first attempt was a RAII-style guard that stops the child in
DESTROY. It worked, but once I let it send TERM first and wait a bit,
it needed signal masking and a few other things, which felt like too
much. Since run's body is wrapped in an eval that catches every die
anyway, a check after the eval seemed to do the same job with a lot
less code, so I went with that.

Things I didn't touch, as they behave like this today already:
- only the direct child gets killed, so commands behind a shell or
  pipe might keep running
- a run timeout longer than the caller's alarm still delays it
- with noerr, a die from the caller's handler still gets swallowed

Both patches add tests to test/cmd-test.pl, and I tried the 'pvesm
alloc' case on a three node test cluster. I might well have missed
something, so any feedback is welcome, including whether the guard
would be the nicer way after all.

Kefu Chai (2):
  cmd: run: do not cancel the caller's alarm
  cmd: run: kill the command when run dies

 src/PVE/Cmd.pm   | 74 +++++++++++++++++++++---------------------------
 test/cmd-test.pl | 68 +++++++++++++++++++++++++++++++++++++++++++-
 2 files changed, 100 insertions(+), 42 deletions(-)

-- 
2.47.3

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

[Kefu Chai]

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.

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

diff --git a/src/PVE/Cmd.pm b/src/PVE/Cmd.pm
index 27c9193..a6bb17d 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;
 
@@ -195,7 +196,10 @@ sub run($cmd, %param) {
 
         local $SIG{ALRM} = sub { die "got timeout\n"; }
             if $timeout;
-        $oldtimeout = alarm($timeout) if $timeout;
+        if ($timeout) {
+            $oldtimeout = alarm($timeout);
+            $armed_at = Time::HiRes::time();
+        }
 
         &$afterfork() if $afterfork;
 
@@ -295,12 +299,12 @@ 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
@@ -308,7 +312,11 @@ sub run($cmd, %param) {
 
     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..191f9f5 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,33 @@ 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");
+}
+
 # TODO:
 # - cover pipe_socket (needs a socket peer)
 # - cover timeouts and the errfunc/logfunc callbacks
-- 
2.47.3

[PATCH common 2/2] cmd: run: kill the command when run dies

[Kefu Chai]

If a signal handler of the caller dies while the command runs, run()
leaves the command running. So 'pvesm alloc' on an RBD pool whose
placement groups never become active fails with

  'storage-<id>'-locked command timed out - aborting

and releases the lock, while 'rbd create' keeps running.

Kill and reap the command after the eval if it was not reaped yet,
which replaces the kill and waitpid calls on the error paths, and drop
the evals around the callbacks that only rethrew. A killed 'rbd create'
may still leave a partial image behind.

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

diff --git a/src/PVE/Cmd.pm b/src/PVE/Cmd.pm
index a6bb17d..581bb93 100644
--- a/src/PVE/Cmd.pm
+++ b/src/PVE/Cmd.pm
@@ -102,6 +102,7 @@ sub run($cmd, %param) {
     my $oldtimeout;
     my $armed_at;
     my $pid;
+    my $reaped;
     my $exitcode = -1;
 
     my $outfunc;
@@ -223,51 +224,30 @@ sub run($cmd, %param) {
             foreach my $h (@handles) {
                 my $buf = '';
                 my $count = sysread($h, $buf, 4096);
-                if (!defined($count)) {
-                    my $err = $!;
-                    kill(9, $pid);
-                    waitpid($pid, 0);
-                    die $err;
-                }
+                die $! if !defined($count);
                 $select->remove($h) if !$count;
                 if ($h eq $reader) {
                     if ($outfunc || $logfunc) {
-                        eval {
-                            while ($buf =~ s/^([^\010\r\n]*)(?:\n|(?:\010)+|\r\n?)//) {
-                                my $line = $outlog . $1;
-                                $outlog = '';
-                                &$outfunc($line) if $outfunc;
-                                &$logfunc($line) if $logfunc;
-                            }
-                            $outlog .= $buf;
-                        };
-                        my $err = $@;
-                        if ($err) {
-                            kill(9, $pid);
-                            waitpid($pid, 0);
-                            die $err;
+                        while ($buf =~ s/^([^\010\r\n]*)(?:\n|(?:\010)+|\r\n?)//) {
+                            my $line = $outlog . $1;
+                            $outlog = '';
+                            &$outfunc($line) if $outfunc;
+                            &$logfunc($line) if $logfunc;
                         }
+                        $outlog .= $buf;
                     } elsif (!$quiet) {
                         print $buf;
                         *STDOUT->flush();
                     }
                 } elsif ($h eq $error) {
                     if ($errfunc || $logfunc) {
-                        eval {
-                            while ($buf =~ s/^([^\010\r\n]*)(?:\n|(?:\010)+|\r\n?)//) {
-                                my $line = $errlog . $1;
-                                $errlog = '';
-                                &$errfunc($line) if $errfunc;
-                                &$logfunc($line) if $logfunc;
-                            }
-                            $errlog .= $buf;
-                        };
-                        my $err = $@;
-                        if ($err) {
-                            kill(9, $pid);
-                            waitpid($pid, 0);
-                            die $err;
+                        while ($buf =~ s/^([^\010\r\n]*)(?:\n|(?:\010)+|\r\n?)//) {
+                            my $line = $errlog . $1;
+                            $errlog = '';
+                            &$errfunc($line) if $errfunc;
+                            &$logfunc($line) if $logfunc;
                         }
+                        $errlog .= $buf;
                     } elsif (!$quiet) {
                         print STDERR $buf;
                         *STDERR->flush();
@@ -282,7 +262,7 @@ sub run($cmd, %param) {
         &$errfunc($errlog) if $errfunc && $errlog;
         &$logfunc($errlog) if $logfunc && $errlog;
 
-        waitpid($pid, 0);
+        $reaped = waitpid($pid, 0); # same statement, so no signal handler runs in between
 
         if ($? == -1) {
             die "failed to execute\n";
@@ -306,6 +286,12 @@ sub run($cmd, %param) {
 
     alarm(0) if $armed_at;
 
+    # whatever made us die, also a signal handler of the caller, the command must not outlive us
+    if ($pid && !$reaped) {
+        kill(9, $pid);
+        waitpid($pid, 0);
+    }
+
     if ($errmsg && $laststderr) {
         &$errfunc(undef); # flush laststderr
     }
@@ -320,8 +306,6 @@ sub run($cmd, %param) {
 
     if ($err) {
         if ($pid && ($err eq "got timeout\n")) {
-            kill(9, $pid);
-            waitpid($pid, 0);
             die "command '$cmdstr' failed: $err";
         }
 
diff --git a/test/cmd-test.pl b/test/cmd-test.pl
index 191f9f5..1dbb0cc 100755
--- a/test/cmd-test.pl
+++ b/test/cmd-test.pl
@@ -10,6 +10,7 @@ use lib '../src';
 
 use PVE::Cmd;
 
+use POSIX ();
 use Test::More;
 use Time::HiRes ();
 
@@ -95,9 +96,46 @@ for my $test ($caller_alarm_tests->@*) {
     cmp_ok($after, '<', 2.5, "run $test->{name} does not delay the caller's alarm");
 }
 
+# run must not leave its command behind when it dies, whatever makes it die
+#
+# name  - when run dies
+# param - parameters for run
+# alarm - seconds until the caller's alarm handler dies
+# err   - expected error
+my $reap_tests = [
+    { name => 'its own timeout fires', param => { timeout => 1 }, err => qr/got timeout/ },
+    {
+        name => 'outfunc dies',
+        param => { outfunc => sub { die "outfunc failed\n" } },
+        err => qr/outfunc failed/,
+    },
+    { name => "the caller's alarm handler dies", alarm => 1, err => qr/caller timed out/ },
+];
+for my $test ($reap_tests->@*) {
+    my $pid;
+    my %param = ($test->{param} // {})->%*;
+    my $outfunc = delete($param{outfunc}) // sub { };
+    eval {
+        local $SIG{ALRM} = sub { die "caller timed out\n" };
+        alarm($test->{alarm}) if $test->{alarm};
+        PVE::Cmd::run(
+            ['sh', '-c', 'echo $$; exec sleep 30'],
+            outfunc => sub { $pid //= $_[0]; $outfunc->(@_) },
+            %param,
+        );
+    };
+    my $err = $@;
+    alarm(0);
+    like($err, $test->{err}, "run dies when $test->{name}");
+    ok(
+        waitpid($pid, POSIX::WNOHANG) == -1 && !kill(0, $pid),
+        "run reaps the command when $test->{name}",
+    );
+}
+
 # TODO:
 # - cover pipe_socket (needs a socket peer)
-# - cover timeouts and the errfunc/logfunc callbacks
+# - cover the errfunc/logfunc callbacks
 # - more tests
 
 done_testing();
-- 
2.47.3