[pve-devel] [PATCH v2 storage] lvm: improve warning in case vgs output contains unexpected lines

[pve-devel] [PATCH v2 storage] lvm: improve warning in case vgs output contains unexpected lines

[Friedrich Weber]

If the metadata archive under /etc/lvm/archive for a particular VG has
a lot of files or is overly large, `vgs` occasionally prints a message
to stdout [1]. Currently, the LVM plugin tries to parse this message
and thus produces the following confusing warnings in the output of
`pvesm status` or the journal (via pvestatd):

Use of uninitialized value $size in int at [...]/LVMPlugin.pm line 133
Use of uninitialized value $free in int at [...]/LVMPlugin.pm line 133
Use of uninitialized value $lvcount in int [...]/LVMPlugin.pm line 133

Reported in enterprise support where LVM picked up on VGs on VM disks
(due to a missing KRBD device filter in the LVM config), and since
several VM disks had VGs with the same name, LVM quickly produced a
lot of files in /etc/lvm/archive.

Reproducible as follows with a VG named `spam`:

    for i in $(seq 8192);
    do vgrename spam spam2; vgrename spam2 spam; done
    rm /etc/lvm/backup/spam; vgs -o vg_name

Output (linebreak for readability):

    Consider pruning spam VG archive with more then 8 MiB in 8268\n
    files (check archiving is needed in lvm.conf).
    VG
    spam

With this patch, the LVM plugin instead prints a human-readable
warning about the unexpected line.

[1] https://sourceware.org/git/?p=lvm2.git;a=blob;f=lib/format_text/archive.c;h=5acf0c04a;hb=38e0c7a1#l222

Signed-off-by: Friedrich Weber <f.weber@proxmox.com>
---

Notes:
    changes from v1 [2]:
    
    * warn about the unexpected line instead of simply ignoring it
    
    [2] https://lists.proxmox.com/pipermail/pve-devel/2024-January/061333.html

 src/PVE/Storage/LVMPlugin.pm | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/src/PVE/Storage/LVMPlugin.pm b/src/PVE/Storage/LVMPlugin.pm
index 4b951e7..5377823 100644
--- a/src/PVE/Storage/LVMPlugin.pm
+++ b/src/PVE/Storage/LVMPlugin.pm
@@ -130,6 +130,11 @@ sub lvm_vgs {
 
 	    my ($name, $size, $free, $lvcount, $pvname, $pvsize, $pvfree) = split (':', $line);
 
+	    if (!defined($size) || !defined($free) || !defined($lvcount)) {
+		warn "unexpected output from vgs: $line\n";
+		return;
+	    }
+
 	    $vgs->{$name} //= {
 		size => int ($size),
 		free => int ($free),
-- 
2.39.2

Re: [pve-devel] [PATCH v2 storage] lvm: improve warning in case vgs output contains unexpected lines

[Fiona Ebner]

Am 18.01.24 um 12:11 schrieb Friedrich Weber:
> diff --git a/src/PVE/Storage/LVMPlugin.pm b/src/PVE/Storage/LVMPlugin.pm
> index 4b951e7..5377823 100644
> --- a/src/PVE/Storage/LVMPlugin.pm
> +++ b/src/PVE/Storage/LVMPlugin.pm
> @@ -130,6 +130,11 @@ sub lvm_vgs {
>  
>  	    my ($name, $size, $free, $lvcount, $pvname, $pvsize, $pvfree) = split (':', $line);
>  
> +	    if (!defined($size) || !defined($free) || !defined($lvcount)) {
> +		warn "unexpected output from vgs: $line\n";
> +		return;
> +	    }
> +

Nit: maybe quote 'vgs' and/or say "command 'vgs'"?

Please use log_warn() from PVE::RESTEnvironment for new warnings, so
they also show up in task logs.

Re: [pve-devel] [PATCH v2 storage] lvm: improve warning in case vgs output contains unexpected lines

[Fiona Ebner]

Am 19.01.24 um 11:59 schrieb Fiona Ebner:
> Am 18.01.24 um 12:11 schrieb Friedrich Weber:
>> diff --git a/src/PVE/Storage/LVMPlugin.pm b/src/PVE/Storage/LVMPlugin.pm
>> index 4b951e7..5377823 100644
>> --- a/src/PVE/Storage/LVMPlugin.pm
>> +++ b/src/PVE/Storage/LVMPlugin.pm
>> @@ -130,6 +130,11 @@ sub lvm_vgs {
>>  
>>  	    my ($name, $size, $free, $lvcount, $pvname, $pvsize, $pvfree) = split (':', $line);
>>  
>> +	    if (!defined($size) || !defined($free) || !defined($lvcount)) {
>> +		warn "unexpected output from vgs: $line\n";
>> +		return;
>> +	    }
>> +
> 
> Nit: maybe quote 'vgs' and/or say "command 'vgs'"?
> 
> Please use log_warn() from PVE::RESTEnvironment for new warnings, so
> they also show up in task logs.

Sorry, I mean "show up more visibly", because they count towards the
warning count shown in the task result.

Re: [pve-devel] [PATCH v2 storage] lvm: improve warning in case vgs output contains unexpected lines

[Friedrich Weber]

On 19/01/2024 12:31, Fiona Ebner wrote:
> Am 19.01.24 um 11:59 schrieb Fiona Ebner:
>> Am 18.01.24 um 12:11 schrieb Friedrich Weber:
>>> diff --git a/src/PVE/Storage/LVMPlugin.pm b/src/PVE/Storage/LVMPlugin.pm
>>> index 4b951e7..5377823 100644
>>> --- a/src/PVE/Storage/LVMPlugin.pm
>>> +++ b/src/PVE/Storage/LVMPlugin.pm
>>> @@ -130,6 +130,11 @@ sub lvm_vgs {
>>>  
>>>  	    my ($name, $size, $free, $lvcount, $pvname, $pvsize, $pvfree) = split (':', $line);
>>>  
>>> +	    if (!defined($size) || !defined($free) || !defined($lvcount)) {
>>> +		warn "unexpected output from vgs: $line\n";
>>> +		return;
>>> +	    }
>>> +
>>
>> Nit: maybe quote 'vgs' and/or say "command 'vgs'"?

Sounds good!

>> Please use log_warn() from PVE::RESTEnvironment for new warnings, so
>> they also show up in task logs.
> 
> Sorry, I mean "show up more visibly", because they count towards the
> warning count shown in the task result.

Thanks, wasn't aware of this benefit of `log_warn`.

Will send a v3 with the two changes.

Re: [pve-devel] [PATCH v2 storage] lvm: improve warning in case vgs output contains unexpected lines

[Friedrich Weber]

On 23/01/2024 11:01, Friedrich Weber wrote:
> On 19/01/2024 12:31, Fiona Ebner wrote:
>> Am 19.01.24 um 11:59 schrieb Fiona Ebner:
[...]
>>> Please use log_warn() from PVE::RESTEnvironment for new warnings, so
>>> they also show up in task logs.
>>
>> Sorry, I mean "show up more visibly", because they count towards the
>> warning count shown in the task result.
> 
> Thanks, wasn't aware of this benefit of `log_warn`.
> 
> Will send a v3 with the two changes.

After changing `warn` to `log_warn` I noticed that pvestatd does not
write the warning to the syslog every 10s anymore. Turns out `warn`
triggers a custom __WARN__ handler we install for our daemons which also
writes to syslog (e.g. pvestatd [1]). But `log_warn` only writes to
stderr [2], thus the `log_warn` warning is not written to the syslog.

Briefly discussed with Fiona off-list, she suggested to try replacing
`print` in `log_warn` with `warn` [2]. But with this, all `log_warn`
warnings also appear in the syslog (e.g. the "no efidisk configured"
warning [3]), which I think would be too spammy.

I'd suggest I use `log_warn` in this patch and keep `log_warn` as it is
(printing only to stderr) for now. The downside is that pvestatd will
not log the `vgs` warning to the syslog anymore (but doing that every 10
seconds could also be considered spammy anyway). The upside is that e.g.
a qmstart task log has the warning in its task log and shows "Warnings:
1" in the GUI, which might be better for visibility than a syslog
message anyway.

What do you think?

[1]
https://git.proxmox.com/?p=pve-manager.git;a=blob;f=bin/pvestatd;h=5cd727e9;hb=d90563e4#l15
[2]
https://git.proxmox.com/?p=pve-common.git;a=blob;f=src/PVE/RESTEnvironment.pm;h=191c6eb;hb=c6ec71d84#l735
[3]
https://git.proxmox.com/?p=qemu-server.git;a=blob;f=PVE/QemuServer.pm;h=b45507aa;hb=eb86f776#l3492

Re: [pve-devel] [PATCH v2 storage] lvm: improve warning in case vgs output contains unexpected lines

[Fiona Ebner]

Am 31.01.24 um 12:55 schrieb Friedrich Weber:
> 
> After changing `warn` to `log_warn` I noticed that pvestatd does not
> write the warning to the syslog every 10s anymore. Turns out `warn`
> triggers a custom __WARN__ handler we install for our daemons which also
> writes to syslog (e.g. pvestatd [1]). But `log_warn` only writes to
> stderr [2], thus the `log_warn` warning is not written to the syslog.
> 
> Briefly discussed with Fiona off-list, she suggested to try replacing
> `print` in `log_warn` with `warn` [2]. But with this, all `log_warn`
> warnings also appear in the syslog (e.g. the "no efidisk configured"
> warning [3]), which I think would be too spammy.
> 

But that is the original intention behind the __WARN__ handler. I'd
argue that replacing a warn with a log_warn() shouldn't change these
semantics. The intention of log_warn() was to make warnings more visible
in task logs. Making them less visible outside of tasks was not intended!

The issue that task warnings also appear in syslog for pvedaemon and
others is a bit orthogonal and can be fixed too.

My proposed solutions:

1) Switch to using "warn" instead of "print STDERR" in log_warn() and
either:
1A) Clear the inherited __WARN__ handler in fork_worker().
1B) Have the __WARN__ handler check if it's in a worker and only log to
syslog if it's not.

2. Keep using "print STDERR" in log_warn() and do print to syslog there
if not in a worker.

> I'd suggest I use `log_warn` in this patch and keep `log_warn` as it is
> (printing only to stderr) for now. The downside is that pvestatd will
> not log the `vgs` warning to the syslog anymore (but doing that every 10
> seconds could also be considered spammy anyway). The upside is that e.g.
> a qmstart task log has the warning in its task log and shows "Warnings:
> 1" in the GUI, which might be better for visibility than a syslog
> message anyway.
> 

This is something that could be solved with an intermediate log level,
but that requires new infrastructure of course. If it important enough
to be a warning, then I don't see an issue with pvestatd logging it. If
it's not, maybe we need a log_info() for such messages (and allow users
to configure if they want infos too)?

> What do you think?
> 
> [1]
> https://git.proxmox.com/?p=pve-manager.git;a=blob;f=bin/pvestatd;h=5cd727e9;hb=d90563e4#l15
> [2]
> https://git.proxmox.com/?p=pve-common.git;a=blob;f=src/PVE/RESTEnvironment.pm;h=191c6eb;hb=c6ec71d84#l735
> [3]
> https://git.proxmox.com/?p=qemu-server.git;a=blob;f=PVE/QemuServer.pm;h=b45507aa;hb=eb86f776#l3492
> 
> 

Re: [pve-devel] [PATCH v2 storage] lvm: improve warning in case vgs output contains unexpected lines

[Fiona Ebner]

Am 01.02.24 um 10:20 schrieb Fiona Ebner:
> Am 31.01.24 um 12:55 schrieb Friedrich Weber:
>>
>> After changing `warn` to `log_warn` I noticed that pvestatd does not
>> write the warning to the syslog every 10s anymore. Turns out `warn`
>> triggers a custom __WARN__ handler we install for our daemons which also
>> writes to syslog (e.g. pvestatd [1]). But `log_warn` only writes to
>> stderr [2], thus the `log_warn` warning is not written to the syslog.
>>
>> Briefly discussed with Fiona off-list, she suggested to try replacing
>> `print` in `log_warn` with `warn` [2]. But with this, all `log_warn`
>> warnings also appear in the syslog (e.g. the "no efidisk configured"
>> warning [3]), which I think would be too spammy.
>>
> 
> But that is the original intention behind the __WARN__ handler. I'd
> argue that replacing a warn with a log_warn() shouldn't change these
> semantics. The intention of log_warn() was to make warnings more visible
> in task logs. Making them less visible outside of tasks was not intended!
> 
> The issue that task warnings also appear in syslog for pvedaemon and
> others is a bit orthogonal and can be fixed too.
> 
> My proposed solutions:
> 
> 1) Switch to using "warn" instead of "print STDERR" in log_warn() and
> either:
> 1A) Clear the inherited __WARN__ handler in fork_worker().
> 1B) Have the __WARN__ handler check if it's in a worker and only log to
> syslog if it's not.
> 
The above would also address instances of "warn" (and not just
log_warn()) that currently end up in syslog even though they happen in a
task worker. OTOH, one could argue such warnings are not visible enough
if not also logged to syslog, because there is no task warning count and
it's not obvious you should read the task log.

> 2. Keep using "print STDERR" in log_warn() and do print to syslog there
> if not in a worker.

We'd also need to check that it's not an interactive invocation, because
for those it should also not log to syslog.

Re: [pve-devel] [PATCH v2 storage] lvm: improve warning in case vgs output contains unexpected lines

[Thomas Lamprecht]

Am 01/02/2024 um 10:20 schrieb Fiona Ebner:
> Am 31.01.24 um 12:55 schrieb Friedrich Weber:
>>
>> After changing `warn` to `log_warn` I noticed that pvestatd does not
>> write the warning to the syslog every 10s anymore. Turns out `warn`
>> triggers a custom __WARN__ handler we install for our daemons which also
>> writes to syslog (e.g. pvestatd [1]). But `log_warn` only writes to
>> stderr [2], thus the `log_warn` warning is not written to the syslog.
>>
>> Briefly discussed with Fiona off-list, she suggested to try replacing
>> `print` in `log_warn` with `warn` [2]. But with this, all `log_warn`
>> warnings also appear in the syslog (e.g. the "no efidisk configured"
>> warning [3]), which I think would be too spammy.
>>
> 
> But that is the original intention behind the __WARN__ handler. I'd
> argue that replacing a warn with a log_warn() shouldn't change these
> semantics. The intention of log_warn() was to make warnings more visible
> in task logs. Making them less visible outside of tasks was not intended!

Not sure if I agree 100% with that, IMO it can be fine to say that both
are different things, not every task log warnings needs to be in the
syslog just like not every syslog warning that happens while being
inside a worker needs to go in the task log.

Albeit it's definitively safer to log task log warnings inside syslog,
as that is mostly accessible for users/api-tokens that have node wide
sys.audit already.

> 
> The issue that task warnings also appear in syslog for pvedaemon and
> others is a bit orthogonal and can be fixed too.
> 
> My proposed solutions:
> 
> 1) Switch to using "warn" instead of "print STDERR" in log_warn() and
> either:
> 1A) Clear the inherited __WARN__ handler in fork_worker().
> 1B) Have the __WARN__ handler check if it's in a worker and only log to
> syslog if it's not.


> 
> 2. Keep using "print STDERR" in log_warn() and do print to syslog there
> if not in a worker.

why not unconditionally? I.e., just call syslog inside log_warn too?
While that would affect a  few CLI usages that might not syslog now, but
one could argue that this would not really matter.


> 
>> I'd suggest I use `log_warn` in this patch and keep `log_warn` as it is
>> (printing only to stderr) for now. The downside is that pvestatd will
>> not log the `vgs` warning to the syslog anymore (but doing that every 10
>> seconds could also be considered spammy anyway). The upside is that e.g.

yeah, some log-rate limiting could sometimes be nice, but that has a
surprisingly high management complexity if one still wants to keep good
UX (i.e., report every X logs, or with a timeout, that a specific log
was suppressed)

>> a qmstart task log has the warning in its task log and shows "Warnings:
>> 1" in the GUI, which might be better for visibility than a syslog
>> message anyway.
>>
> 
> This is something that could be solved with an intermediate log level,
> but that requires new infrastructure of course. If it important enough
> to be a warning, then I don't see an issue with pvestatd logging it. If
> it's not, maybe we need a log_info() for such messages (and allow users
> to configure if they want infos too)?

We can too all the levels, log_notice could even show up in the UI,
log_info would be regular without special task state.
But that would not solve the question about when to log to syslog too,
as that's not something that one can derive just from the log level IMO.