[PATCH storage] lvm: bound storage status commands

[Thomas Lamprecht <t.lamprecht@proxmox.com>]

A status command stuck in uninterruptible device I/O blocks storage
status indefinitely: run_command waits for its child, and SIGKILL does
not end such a command. That happens for example when all paths of a
multipath map that queues I/O are gone. pvestatd and API calls that
query the storage status then hang with it.

Run the vgs, lvs and pvscan calls of a status pass through a killable
Perl child, with a 15-second limit including lock acquisition. The
command inherits a lock and keeps it until it really exits, so later
passes cannot pile up commands on the same failed device. While a
command is stuck, LVM storages are reported inactive; other storages
are not affected.

Signed-off-by: Thomas Lamprecht <t.lamprecht@proxmox.com>
---

This was part of v3 of the SAN series [0], with a new run_command() mode
and a hand-over across the daemon re-exec. It is independent of that
series and could be remodelled so that the existing
run_fork_with_timeout() is enough, and nothing changes for callers
outside of a status pass.

Tested on a nested cluster with a shared volume group on a two-path
iSCSI LUN whose map queues forever, with stock libpve-common-perl: with
all paths cut for three minutes, one killed vgs stays in state D as a
child of init and holds the lock, pvestatd keeps running, and the
storage status API keeps answering with the LVM storages inactive. A
pass spends 14 seconds waiting for the lock; the rest of the 27 seconds
per API call there are the portal checks of the unreachable iSCSI
target, as before. Everything is active again at the first check ten
seconds after the paths return.

Known limits:

 - The status commands of all callers on a node (pvestatd, API workers,
   pvesm) now run one after the other. A caller whose wait for the lock
   plus its own command exceed 14 seconds reports the LVM storages
   inactive for that pass. vgs takes 0.05 seconds on the test nodes
   with 36 PVs, so this needs very slow listings and several callers at
   once.
 - Activating an inactive thin pool (lvchange) is not bounded, as on
   master: killing an activation midway would be worse.
 - A SIGTERM that arrives while run_fork_with_timeout() waits is
   consumed there, as for the df fork of directory storages today, where
   the window is much shorter. Stopping pvestatd during that wait
   therefore ends with the SIGKILL fallback of the stop command after
   five seconds. That is for run_fork_with_timeout() to fix.
 - The stuck command stays in the control group of the service that
   started it. If that is pvestatd, systemctl stop and restart wait
   for the command or for systemd's stop timeout (68 seconds in the
   test, until the target's default queueing gave up); a reload
   re-executes the daemon and does not wait. On master the daemon
   hangs with the command in that situation.

[0]: https://lore.proxmox.com/pve-devel/20261105233336.2178064-1-t.lamprecht@proxmox.com/

 src/PVE/Storage.pm               |   2 +-
 src/PVE/Storage/LVMPlugin.pm     |  88 +++++++++--
 src/PVE/Storage/LvmThinPlugin.pm |   4 +-
 src/test/Makefile                |   5 +-
 src/test/run_test_lvm_status.pl  | 243 +++++++++++++++++++++++++++++++
 5 files changed, 328 insertions(+), 14 deletions(-)
 create mode 100755 src/test/run_test_lvm_status.pl

diff --git a/src/PVE/Storage.pm b/src/PVE/Storage.pm
index be6e9743..bf065e72 100755
--- a/src/PVE/Storage.pm
+++ b/src/PVE/Storage.pm
@@ -1493,7 +1493,7 @@ sub storage_info {
         push @$slist, $storeid;
     }
 
-    my $cache = {};
+    my $cache = { status_only => 1 };
 
     foreach my $storeid (keys %$ids) {
         my $scfg = $ids->{$storeid};
diff --git a/src/PVE/Storage/LVMPlugin.pm b/src/PVE/Storage/LVMPlugin.pm
index 1b0c8020..b2cfa858 100644
--- a/src/PVE/Storage/LVMPlugin.pm
+++ b/src/PVE/Storage/LVMPlugin.pm
@@ -4,7 +4,7 @@ use strict;
 use warnings;
 
 use Cwd qw(abs_path);
-use Fcntl qw(O_RDWR O_EXCL);
+use Fcntl qw(O_RDWR O_EXCL O_CREAT :flock);
 use File::Basename;
 use IO::File;
 use JSON;
@@ -269,8 +269,69 @@ sub lvm_destroy_volume_group {
     );
 }
 
+our $LVM_STATUS_TIMEOUT = 15;
+our $LVM_STATUS_LOCK = '/run/pve-storage-lvm-status.lock';
+
+sub run_lvm_command {
+    my ($cache, $cmd, %param) = @_;
+
+    return run_command($cmd, %param) if !$cache || !$cache->{status_only};
+    die $cache->{'lvm-status-error'} if $cache->{'lvm-status-error'};
+
+    my $deadline = clock_gettime(CLOCK_MONOTONIC) + $LVM_STATUS_TIMEOUT - 1;
+    my ($result, $timed_out);
+    eval {
+        ($result, $timed_out) = PVE::Tools::run_fork_with_timeout(
+            $LVM_STATUS_TIMEOUT,
+            sub {
+                # the handlers of the caller, like the shutdown of a daemon, are not for this child
+                $SIG{INT} = $SIG{TERM} = $SIG{QUIT} = 'DEFAULT';
+
+                sysopen(my $lock, $LVM_STATUS_LOCK, O_RDWR | O_CREAT, 0600)
+                    or die "unable to open '$LVM_STATUS_LOCK' - $!\n";
+                my (undef, $lock_timeout) = PVE::Tools::run_with_timeout(
+                    $deadline - clock_gettime(CLOCK_MONOTONIC),
+                    sub {
+                        flock($lock, LOCK_EX) or die "unable to lock '$LVM_STATUS_LOCK' - $!\n";
+                    },
+                );
+                die "LVM status unavailable - another LVM status command is still running\n"
+                    if $lock_timeout;
+
+                my $left = $deadline - clock_gettime(CLOCK_MONOTONIC);
+                die "LVM status unavailable - time limit reached\n" if $left <= 0;
+
+                # The command gets the lock as stdin: LVM closes other descriptors, and a command
+                # stuck in I/O must keep the lock after the killable Perl child exits.
+                my @output;
+                eval {
+                    run_command(
+                        $cmd,
+                        %param,
+                        timeout => $left,
+                        input => '<&' . fileno($lock),
+                        $param{outfunc} ? (outfunc => sub { push @output, $_[0] }) : (),
+                    );
+                };
+                return { output => \@output, error => "$@" };
+            },
+        );
+        die "LVM status unavailable - '$cmd->[0]' or lock acquisition timed out\n"
+            if $timed_out;
+        die "LVM status unavailable - no result from '$cmd->[0]'\n" if !$result;
+        die $result->{error} if $result->{error} =~ m/got timeout\n\z/;
+    };
+    if (my $err = $@) {
+        $cache->{'lvm-status-error'} = $err;
+        die $err;
+    }
+
+    $param{outfunc}->($_) for $result->{output}->@*;
+    die $result->{error} if $result->{error};
+}
+
 sub lvm_vgs {
-    my ($includepvs, $nohints) = @_;
+    my ($includepvs, $nohints, $cache) = @_;
 
     my $cmd = [
         '/sbin/vgs',
@@ -295,7 +356,8 @@ sub lvm_vgs {
 
     my $vgs = {};
     eval {
-        run_command(
+        run_lvm_command(
+            $cache,
             $cmd,
             outfunc => sub {
                 my $line = shift;
@@ -324,6 +386,8 @@ sub lvm_vgs {
     };
     my $err = $@;
 
+    die $err if $err && $cache && $cache->{'lvm-status-error'};
+
     # just warn (vgs return error code 5 if clvmd does not run)
     # but output is still OK (list without clustered VGs)
     warn $err if $err;
@@ -332,7 +396,7 @@ sub lvm_vgs {
 }
 
 sub lvm_list_volumes {
-    my ($vgname) = @_;
+    my ($vgname, $cache) = @_;
 
     my $option_list =
         'vg_name,lv_name,lv_size,lv_attr,pool_lv,data_percent,metadata_percent,snap_percent,uuid,tags,metadata_size,time';
@@ -355,7 +419,8 @@ sub lvm_list_volumes {
     push @$cmd, $vgname if $vgname;
 
     my $lvs = {};
-    run_command(
+    run_lvm_command(
+        $cache,
         $cmd,
         outfunc => sub {
             my $line = shift;
@@ -1511,7 +1576,7 @@ sub list_images {
 sub status {
     my ($class, $storeid, $scfg, $cache) = @_;
 
-    $cache->{vgs} = lvm_vgs() if !$cache->{vgs};
+    $cache->{vgs} = lvm_vgs(undef, undef, $cache) if !$cache->{vgs};
 
     my $vgname = $scfg->{vgname};
 
@@ -1587,14 +1652,17 @@ my sub find_unhinted_vgs {
 
     $cache->{vgscaned} = 1;
 
-    my $vgs = lvm_vgs(0, 1);
+    my $vgs = lvm_vgs(0, 1, $cache);
     my @unhinted = grep { !$cache->{vgs}->{$_} } sort keys %$vgs;
     return if !@unhinted;
 
     eval {
-        run_command(['/sbin/pvscan', '--cache'], outfunc => sub { });
+        run_lvm_command($cache, ['/sbin/pvscan', '--cache'], outfunc => sub { });
     };
-    warn "rebuilding the LVM device hints failed - $@" if $@;
+    if (my $err = $@) {
+        die $err if $cache->{'lvm-status-error'};
+        warn "rebuilding the LVM device hints failed - $err";
+    }
 
     # add, never replace: an incomplete listing must not hide volume groups found before
     $cache->{vgs}->{$_} = $vgs->{$_} for @unhinted;
@@ -1605,7 +1673,7 @@ my sub find_unhinted_vgs {
 sub activate_storage {
     my ($class, $storeid, $scfg, $cache) = @_;
 
-    $cache->{vgs} = lvm_vgs() if !$cache->{vgs};
+    $cache->{vgs} = lvm_vgs(undef, undef, $cache) if !$cache->{vgs};
 
     find_unhinted_vgs($cache) if !$cache->{vgscaned} && !$cache->{vgs}->{ $scfg->{vgname} };
 
diff --git a/src/PVE/Storage/LvmThinPlugin.pm b/src/PVE/Storage/LvmThinPlugin.pm
index 8698495d..4c7ab98f 100644
--- a/src/PVE/Storage/LvmThinPlugin.pm
+++ b/src/PVE/Storage/LvmThinPlugin.pm
@@ -229,7 +229,7 @@ sub list_thinpools {
 sub status {
     my ($class, $storeid, $scfg, $cache) = @_;
 
-    my $lvs = $cache->{lvs} ||= PVE::Storage::LVMPlugin::lvm_list_volumes();
+    my $lvs = $cache->{lvs} ||= PVE::Storage::LVMPlugin::lvm_list_volumes(undef, $cache);
 
     return if !$lvs->{ $scfg->{vgname} };
 
@@ -248,7 +248,7 @@ sub status {
 my $activate_lv = sub {
     my ($vg, $lv, $cache) = @_;
 
-    my $lvs = $cache->{lvs} ||= PVE::Storage::LVMPlugin::lvm_list_volumes();
+    my $lvs = $cache->{lvs} ||= PVE::Storage::LVMPlugin::lvm_list_volumes(undef, $cache);
 
     die "no such logical volume $vg/$lv\n" if !$lvs->{$vg} || !$lvs->{$vg}->{$lv};
 
diff --git a/src/test/Makefile b/src/test/Makefile
index 185b8ef7..9c2710df 100644
--- a/src/test/Makefile
+++ b/src/test/Makefile
@@ -1,6 +1,6 @@
 all: test
 
-test: test_iscsi test_zfspoolplugin test_lvmplugin test_lvm_create test_lvm_lock_retry test_lvm_base_volume test_lvm_hints test_disklist test_bwlimit test_plugin test_ovf test_volume_access test_remote_command
+test: test_iscsi test_zfspoolplugin test_lvmplugin test_lvm_create test_lvm_lock_retry test_lvm_base_volume test_lvm_hints test_lvm_status test_disklist test_bwlimit test_plugin test_ovf test_volume_access test_remote_command
 
 test_zfspoolplugin: run_test_zfspoolplugin.pl
 	./run_test_zfspoolplugin.pl
@@ -22,6 +22,9 @@ test_lvm_base_volume: run_test_lvm_base_volume.pl
 test_lvm_hints: run_test_lvm_hints.pl
 	./run_test_lvm_hints.pl
 
+test_lvm_status: run_test_lvm_status.pl
+	./run_test_lvm_status.pl
+
 test_disklist: run_disk_tests.pl
 	./run_disk_tests.pl
 
diff --git a/src/test/run_test_lvm_status.pl b/src/test/run_test_lvm_status.pl
new file mode 100755
index 00000000..fc2ba486
--- /dev/null
+++ b/src/test/run_test_lvm_status.pl
@@ -0,0 +1,243 @@
+#!/usr/bin/perl
+
+use strict;
+use warnings;
+
+our $ignore_command_kill = 0;
+
+BEGIN {
+    *CORE::GLOBAL::kill = sub {
+        # Model an unkillable command without preventing run_fork_with_timeout from killing Perl.
+        return scalar(@_) - 1 if $ignore_command_kill && caller eq 'PVE::Cmd';
+        return CORE::kill(@_);
+    };
+}
+
+use lib '..';
+use Cwd qw(abs_path);
+use Fcntl qw(:flock O_CREAT O_RDWR);
+use File::Temp qw(tempdir);
+use Test::MockModule;
+use Test::More;
+
+use PVE::Storage;
+use PVE::Syscall;
+
+my $dir = tempdir('lvm-status-XXXXXX', DIR => '.', CLEANUP => 1);
+local $PVE::Storage::LVMPlugin::LVM_STATUS_LOCK = "$dir/lock";
+local $PVE::Storage::LVMPlugin::LVM_STATUS_TIMEOUT = 10;
+
+my $lvm = Test::MockModule->new('PVE::Storage::LVMPlugin');
+my $storage = Test::MockModule->new('PVE::Storage');
+$storage->mock(uevent_seqnum => sub { return 1 });
+my $directory = Test::MockModule->new('PVE::Storage::DirPlugin');
+$directory->mock(
+    activate_storage => sub { },
+    status => sub { return (1024, 512, 512, 1) },
+);
+
+my $cfg = {
+    ids => {
+        lvm1 => { type => 'lvm', vgname => 'vg1', content => { images => 1 } },
+        lvm2 => { type => 'lvm', vgname => 'vg2', content => { images => 1 } },
+        thin => {
+            type => 'lvmthin',
+            vgname => 'vg1',
+            thinpool => 'pool',
+            content => { images => 1 },
+        },
+        local => { type => 'dir', path => $dir, content => { iso => 1 } },
+    },
+};
+my $thin_cfg = { ids => { thin => $cfg->{ids}->{thin}, local => $cfg->{ids}->{local} } };
+my $vgs = ['vg1:1024:512:1', 'vg2:2048:1024:0'];
+my $lvs = ['vg1:pool:1048576:twi---tz--::10.00:5.00::uuid::4096:0'];
+my $script;
+my $real_run = \&PVE::Storage::LVMPlugin::run_command;
+$lvm->mock(
+    run_command => sub {
+        my ($cmd, %param) = @_;
+        die "status command without a timeout\n" if !$param{timeout};
+        my $name = $cmd->[0] =~ s|.*/||r;
+        $name .= ' --nohints' if grep { $_ eq '--nohints' } @$cmd;
+        open(my $log, '>>', "$dir/calls") or die $!;
+        print {$log} "$name\n";
+        close($log);
+        my $action = $script->{$name} // [];
+        my $replacement = ref($action) eq 'HASH' ? $action->{cmd} : [
+            $^X, '-e', 'print "$_\n" for @ARGV', @$action,
+        ];
+        # only the slow command gets a short limit, the fast ones before it keep a wide margin
+        $param{timeout} = $action->{timeout} if ref($action) eq 'HASH' && $action->{timeout};
+        return $real_run->($replacement, %param);
+    },
+);
+my $thin = Test::MockModule->new('PVE::Storage::LvmThinPlugin');
+$thin->mock(
+    run_command => sub {
+        my ($cmd, %param) = @_;
+        die "thin pool activation with a timeout\n" if $param{timeout};
+        open(my $log, '>>', "$dir/calls") or die $!;
+        print {$log} "$cmd->[0]\n";
+        close($log);
+        return 0;
+    },
+);
+
+my sub calls {
+    return [split(/\n/, PVE::Tools::file_get_contents("$dir/calls"))];
+}
+
+my sub pass {
+    my ($commands, $config) = @_;
+    $script = $commands;
+    PVE::Tools::file_set_contents("$dir/calls", '');
+    my @warnings;
+    local $SIG{__WARN__} = sub { push @warnings, $_[0] };
+    my $info = PVE::Storage::storage_info($config // $cfg);
+    return ($info, \@warnings);
+}
+
+my ($info, $warnings) = pass({ vgs => $vgs, lvs => $lvs });
+is_deeply(
+    [map { $info->{$_}->{active} } qw(lvm1 lvm2 thin local)],
+    [1, 1, 1, 1],
+    'normal status activates an inactive thin pool and reports all storages',
+);
+is_deeply([sort @{ calls() }], [qw(lvchange lvs vgs)], 'listings are cached across storages');
+is_deeply($warnings, [], 'normal status has no warnings');
+is($info->{lvm1}->{total}, 1024, 'VG sizes cross the fork');
+is($info->{thin}->{used}, 104857, 'LV usage crosses the fork');
+
+($info, $warnings) = pass({
+    vgs => { cmd => [$^X, '-e', 'print "$_\n" for @ARGV; exit 5', @$vgs] },
+    lvs => $lvs,
+});
+is_deeply(
+    [map { $info->{$_}->{active} } qw(lvm1 lvm2 thin)],
+    [1, 1, 1],
+    'ordinary vgs failure keeps the partial listing and permits later commands',
+);
+like(join('', @$warnings), qr/exit code 5/, 'ordinary vgs failure still warns');
+
+($info, $warnings) = pass({
+    vgs => [],
+    'vgs --nohints' => $vgs,
+    lvs => $lvs,
+});
+is($info->{thin}->{active}, 1, 'a VG missing from hints is found and activated');
+is_deeply(
+    [sort @{ calls() }],
+    ['lvchange', 'lvs', 'pvscan', 'vgs', 'vgs --nohints'],
+    'hint recovery runs bounded vgs and pvscan',
+);
+
+($info, $warnings) = pass({
+    vgs => [],
+    'vgs --nohints' => $vgs,
+    lvs => $lvs,
+    pvscan => { cmd => [$^X, '-e', 'exit 5'] },
+});
+is($info->{thin}->{active}, 1, 'ordinary pvscan failure keeps the discovered VG');
+like(join('', @$warnings), qr/rebuilding the LVM device hints failed/, 'pvscan failure warns');
+
+($info, $warnings) =
+    pass({ vgs => { cmd => [$^X, '-e', 'kill("KILL", getppid())'] }, lvs => $lvs });
+is($info->{lvm1}->{active}, 0, 'a child that dies without a result is no empty listing');
+like(join('', @$warnings), qr/no result from/, 'the missing result is reported');
+
+{
+    local $SIG{TERM} = sub { PVE::Tools::file_set_contents("$dir/handler", $$) };
+    ($info, $warnings) =
+        pass({ vgs => { cmd => [$^X, '-e', 'kill("TERM", getppid())'] }, lvs => $lvs });
+    ok(!-e "$dir/handler", 'the forked child does not run the signal handlers of the caller');
+    like(join('', @$warnings), qr/no result from/, 'the terminated child is reported');
+}
+
+{
+    my $slow = { cmd => [$^X, '-e', 'sleep 60'], timeout => 1 };
+    for my $command ('vgs', 'vgs --nohints', 'pvscan', 'lvs') {
+        my $commands = { vgs => $vgs, lvs => $lvs, $command => $slow };
+        if ($command eq 'vgs --nohints' || $command eq 'pvscan') {
+            $commands->{vgs} = [];
+            $commands->{'vgs --nohints'} //= $vgs;
+        }
+        ($info, $warnings) = pass($commands, $thin_cfg);
+        is($info->{thin}->{active}, 0, "$command timeout makes the storage inactive");
+        is($info->{local}->{active}, 1, "$command timeout does not affect other plugins");
+        like(join('', @$warnings), qr/(?:got timeout|timed out)/, "$command timeout is reported");
+        is(calls()->[-1], $command, "no command follows the $command timeout");
+    }
+
+    ($info, $warnings) = pass({ vgs => $slow, lvs => $lvs });
+    is_deeply(
+        [map { $info->{$_}->{active} } qw(lvm1 lvm2 thin)],
+        [0, 0, 0],
+        'a timed out first listing makes all LVM storages inactive',
+    );
+    is_deeply(calls(), ['vgs'], 'the failed listing is not retried within the pass');
+
+    local $PVE::Storage::LVMPlugin::LVM_STATUS_TIMEOUT = 2;
+    sysopen(my $lock, "$dir/lock", O_RDWR | O_CREAT, 0600) or die $!;
+    flock($lock, LOCK_EX) or die $!;
+    for (1 .. 2) {
+        ($info, $warnings) = pass({ vgs => $vgs, lvs => $lvs });
+        is_deeply(
+            [map { $info->{$_}->{active} } qw(lvm1 lvm2 thin local)],
+            [0, 0, 0, 1],
+            'a held lock makes only LVM storages inactive',
+        );
+        like(
+            join('', @$warnings),
+            qr/(?:another LVM status command is still running|timed out|got timeout)/,
+            'lock contention is reported',
+        );
+        is_deeply(calls(), [], 'a pass waiting for the lock starts no commands');
+    }
+    close($lock);
+}
+
+($info) = pass({ vgs => $vgs, lvs => $lvs });
+is($info->{thin}->{active}, 1, 'a new pass recovers after the lock is released');
+
+# Adopt the simulated stuck command for deterministic cleanup, as init does for a daemon.
+syscall(PVE::Syscall::prctl(), 36, 1, 0, 0, 0) == 0
+    or die "cannot become a child subreaper: $!";
+{
+    local $ignore_command_kill = 1;
+    my $cache = { status_only => 1 };
+    $script = {
+        vgs => {
+            cmd => [
+                $^X,
+                '-e',
+                'open(my $fh, ">", $ARGV[0]) or die $!; print {$fh} "$$\n"; close($fh); sleep 60',
+                "$dir/pid",
+            ],
+        },
+    };
+    eval { PVE::Storage::LVMPlugin::lvm_vgs(undef, undef, $cache) };
+    like($@, qr/timed out/, 'the outer timeout returns even when the command cannot be killed');
+    my $pid = PVE::Tools::file_read_firstline("$dir/pid");
+    ok($pid && kill(0, $pid), 'the command outlives the Perl child');
+    sysopen(my $lock, "$dir/lock", O_RDWR) or die $!;
+    ok(!flock($lock, LOCK_EX | LOCK_NB), 'the execed command retains the lock');
+    is(readlink("/proc/$pid/fd/0"), abs_path("$dir/lock"), 'stdin holds the lock');
+    local $PVE::Storage::LVMPlugin::LVM_STATUS_TIMEOUT = 2;
+
+    for (1 .. 2) {
+        ($info, $warnings) = pass({ vgs => $vgs, lvs => $lvs });
+        is($info->{lvm1}->{active}, 0, 'later passes report inactive while the command survives');
+        is_deeply(calls(), [], 'later passes start no additional command');
+    }
+    CORE::kill('KILL', $pid);
+    is(waitpid($pid, 0), $pid, 'the orphan was adopted and is reaped by the test');
+    ok(flock($lock, LOCK_EX | LOCK_NB), 'the lock is released only after the command exits');
+}
+
+my %plain;
+$lvm->mock(run_command => sub { my ($cmd, %param) = @_; %plain = %param; return 0 });
+PVE::Storage::LVMPlugin::lvm_vgs(undef, undef, {});
+ok(!exists($plain{timeout}) && !exists($plain{input}), 'non-status callers keep the plain runner');
+
+done_testing();