[pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[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]. 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

[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>
---
 src/PVE/Storage/LVMPlugin.pm | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/src/PVE/Storage/LVMPlugin.pm b/src/PVE/Storage/LVMPlugin.pm
index 4b951e7..557d602 100644
--- a/src/PVE/Storage/LVMPlugin.pm
+++ b/src/PVE/Storage/LVMPlugin.pm
@@ -130,6 +130,9 @@ sub lvm_vgs {
 
 	    my ($name, $size, $free, $lvcount, $pvname, $pvsize, $pvfree) = split (':', $line);
 
+	    # skip human-readable messages that vgs occasionally prints to stdout
+	    return if !defined($size);
+
 	    $vgs->{$name} //= {
 		size => int ($size),
 		free => int ($free),
-- 
2.39.2

Re: [pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[Fiona Ebner]

Am 11.01.24 um 17:58 schrieb Friedrich Weber:
> 
> [1] https://sourceware.org/git/?p=lvm2.git;a=blob;f=lib/format_text/archive.c;h=5acf0c04a;hb=38e0c7a1#l222
> 

>  222                 log_print_unless_silent("Consider pruning %s VG archive with more then %u MiB in %u files (see archiving settings in lvm.conf).",
>  223                                         vgname, (unsigned)sum, archives_size);

Can we pass a silent flag when invoking the command instead?

Re: [pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[Friedrich Weber]

On 12/01/2024 09:57, Fiona Ebner wrote:
> Am 11.01.24 um 17:58 schrieb Friedrich Weber:
>>
>> [1] https://sourceware.org/git/?p=lvm2.git;a=blob;f=lib/format_text/archive.c;h=5acf0c04a;hb=38e0c7a1#l222
>>
> 
>>  222                 log_print_unless_silent("Consider pruning %s VG archive with more then %u MiB in %u files (see archiving settings in lvm.conf).",
>>  223                                         vgname, (unsigned)sum, archives_size);
> 
> Can we pass a silent flag when invoking the command instead?

Good point. A quick test shows passing `-q` does not suppress the
message, but passing `-qq` does. Documentation on `-qq` [1]:

> -q|--quiet ...
> Suppress output and log messages. Overrides --debug and --verbose.
Repeat once to also suppress any prompts with answer 'no'.

Not sure if automatically answering prompts with 'no' might cause
problems -- I don't think I've ever seen a yes/no prompt by `vgs`
though. What do you think?

[1] https://manpages.debian.org/bookworm/lvm2/vgs.8.en.html

Re: [pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[Fiona Ebner]

Am 12.01.24 um 10:09 schrieb Friedrich Weber:
> On 12/01/2024 09:57, Fiona Ebner wrote:
>> Am 11.01.24 um 17:58 schrieb Friedrich Weber:
>>>
>>> [1] https://sourceware.org/git/?p=lvm2.git;a=blob;f=lib/format_text/archive.c;h=5acf0c04a;hb=38e0c7a1#l222
>>>
>>
>>>  222                 log_print_unless_silent("Consider pruning %s VG archive with more then %u MiB in %u files (see archiving settings in lvm.conf).",
>>>  223                                         vgname, (unsigned)sum, archives_size);
>>
>> Can we pass a silent flag when invoking the command instead?
> 
> Good point. A quick test shows passing `-q` does not suppress the
> message, but passing `-qq` does. Documentation on `-qq` [1]:
> 
>> -q|--quiet ...
>> Suppress output and log messages. Overrides --debug and --verbose.
> Repeat once to also suppress any prompts with answer 'no'.
> 

That actually sounds like a single -q should be enough, but oh well...

> Not sure if automatically answering prompts with 'no' might cause
> problems -- I don't think I've ever seen a yes/no prompt by `vgs`
> though. What do you think?
> 

Since it's only for listing images, I'd be rather surprised by such a
prompt. And I really hope 'no' would then be the safe option ;)

Re: [pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[Fabian Grünbichler]

On January 11, 2024 5:58 pm, Friedrich Weber wrote:
> 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]. 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
> 
> [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>
> ---
>  src/PVE/Storage/LVMPlugin.pm | 3 +++
>  1 file changed, 3 insertions(+)
> 
> diff --git a/src/PVE/Storage/LVMPlugin.pm b/src/PVE/Storage/LVMPlugin.pm
> index 4b951e7..557d602 100644
> --- a/src/PVE/Storage/LVMPlugin.pm
> +++ b/src/PVE/Storage/LVMPlugin.pm
> @@ -130,6 +130,9 @@ sub lvm_vgs {
>  
>  	    my ($name, $size, $free, $lvcount, $pvname, $pvsize, $pvfree) = split (':', $line);
>  
> +	    # skip human-readable messages that vgs occasionally prints to stdout
> +	    return if !defined($size);
> +

we might want to either log this message (like anything printed to
STDERR), so that the admin at least can notice something weird is going
on, or pass '-qq' to switch `vgs` into silent mode where no such
messages will be printed - although for the latter variant we might want
to check what (else) gets suppressed ("log_print_unless_silent")..

AFAICT this message only gets printed if the archives grew very big, and
the backup file does not exist? at least for me using your reproducer,
it's only printed once, and I have to rename rename rm again afterwards
to get it to show up again, which would mean it's not too bad to log it
(as long as it doesn't confuse our code).

the `lvmscan` endpoint also picks up the line btw, which means it ends
up being included in the "VG" selector on the web UI when adding an LVM
storage ;)

>  	    $vgs->{$name} //= {
>  		size => int ($size),
>  		free => int ($free),
> -- 
> 2.39.2
> 
> 
> 
> _______________________________________________
> pve-devel mailing list
> pve-devel@lists.proxmox.com
> https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel
> 
> 
> 

Re: [pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[Friedrich Weber]

On 12/01/2024 10:22, Fabian Grünbichler wrote:
>> --- a/src/PVE/Storage/LVMPlugin.pm
>> +++ b/src/PVE/Storage/LVMPlugin.pm
>> @@ -130,6 +130,9 @@ sub lvm_vgs {
>>  
>>  	    my ($name, $size, $free, $lvcount, $pvname, $pvsize, $pvfree) = split (':', $line);
>>  
>> +	    # skip human-readable messages that vgs occasionally prints to stdout
>> +	    return if !defined($size);
>> +
> 
> we might want to either log this message (like anything printed to
> STDERR), so that the admin at least can notice something weird is going
> on,

The vgs message is printed to stdout, so we could do something like

warn $line if !defined($size);

?

> or pass '-qq' to switch `vgs` into silent mode where no such
> messages will be printed - although for the latter variant we might want
> to check what (else) gets suppressed ("log_print_unless_silent")..

True. As discussed in the other subthread with Fiona, `-qq` will also
silently answer any prompts with 'no', but it does seem unlikely that
`vgs` ever prompts. So passing `-qq` might be an okay option.

> AFAICT this message only gets printed if the archives grew very big, and
> the backup file does not exist? at least for me using your reproducer,
> it's only printed once, and I have to rename rename rm again afterwards
> to get it to show up again, which would mean it's not too bad to log it
> (as long as it doesn't confuse our code).

For the user in enterprise support I mentioned in the commit message,
the warnings were logged to the journal by pvestatd every few seconds
(without any manual deletion of backup files or similar). I'd need to
look at the source again to be sure, but IIRC the message is also
printed if the backup exists but is outdated (and the archives are very
big). And because LVM got confused by the duplicate VG names, this
situation seemed to occur every few seconds.

Another complication I forgot about: For that user, /etc/lvm/archive had
800000 files amounting to >1GiB, which also slowed down `vgs -o vg_name`
considerably (to >10s), presumably because `vgs -o vg_name` read all
those files. But unexpectedly, as soon as `-o` included `pv_name` the
command was fast again, presumably because it does not do the reads. So
I was considering to modify `sub lvm_vgs` to always include `-o pv_name`
in the command (not only if $includepvs is true), but was unsure if the
edge case warranted this (somewhat weird) workaround.

> the `lvmscan` endpoint also picks up the line btw, which means it ends
> up being included in the "VG" selector on the web UI when adding an LVM
> storage ;)

Hah, fun :)

By the way, the message also causes `vgs` to print invalid JSON:

# rm -f /etc/lvm/backup/spam ; vgs -o vg_name -q --reportformat json
2>/dev/null
  {
      "report": [
  Consider pruning spam VG archive with more then 8 MiB in 8305 files
(check archiving is needed in lvm.conf).
          {
              "vg": [
                  {"vg_name":"pve"},
                  {"vg_name":"spam"},
                  {"vg_name":"testvg"}
              ]
          }
      ]
  }

Dominik suggested that this very much looks like an LVM bug, so I'll
check whether it still happens on latest upstream LVM and, if yes, file
a bug report there.

Re: [pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[Fabian Grünbichler]

On January 12, 2024 11:06 am, Friedrich Weber wrote:
> On 12/01/2024 10:22, Fabian Grünbichler wrote:
>>> --- a/src/PVE/Storage/LVMPlugin.pm
>>> +++ b/src/PVE/Storage/LVMPlugin.pm
>>> @@ -130,6 +130,9 @@ sub lvm_vgs {
>>>  
>>>  	    my ($name, $size, $free, $lvcount, $pvname, $pvsize, $pvfree) = split (':', $line);
>>>  
>>> +	    # skip human-readable messages that vgs occasionally prints to stdout
>>> +	    return if !defined($size);
>>> +
>> 
>> we might want to either log this message (like anything printed to
>> STDERR), so that the admin at least can notice something weird is going
>> on,
> 
> The vgs message is printed to stdout, so we could do something like
> 
> warn $line if !defined($size);
> 
> ?

yep, that would be an option (warn+return ;))

[..]

>> AFAICT this message only gets printed if the archives grew very big, and
>> the backup file does not exist? at least for me using your reproducer,
>> it's only printed once, and I have to rename rename rm again afterwards
>> to get it to show up again, which would mean it's not too bad to log it
>> (as long as it doesn't confuse our code).
> 
> For the user in enterprise support I mentioned in the commit message,
> the warnings were logged to the journal by pvestatd every few seconds
> (without any manual deletion of backup files or similar). I'd need to
> look at the source again to be sure, but IIRC the message is also
> printed if the backup exists but is outdated (and the archives are very
> big). And because LVM got confused by the duplicate VG names, this
> situation seemed to occur every few seconds.
> 
> Another complication I forgot about: For that user, /etc/lvm/archive had
> 800000 files amounting to >1GiB, which also slowed down `vgs -o vg_name`
> considerably (to >10s), presumably because `vgs -o vg_name` read all
> those files. But unexpectedly, as soon as `-o` included `pv_name` the
> command was fast again, presumably because it does not do the reads. So
> I was considering to modify `sub lvm_vgs` to always include `-o pv_name`
> in the command (not only if $includepvs is true), but was unsure if the
> edge case warranted this (somewhat weird) workaround.

that sounds weird ;)

>> the `lvmscan` endpoint also picks up the line btw, which means it ends
>> up being included in the "VG" selector on the web UI when adding an LVM
>> storage ;)
> 
> Hah, fun :)
> 
> By the way, the message also causes `vgs` to print invalid JSON:
> 
> # rm -f /etc/lvm/backup/spam ; vgs -o vg_name -q --reportformat json
> 2>/dev/null
>   {
>       "report": [
>   Consider pruning spam VG archive with more then 8 MiB in 8305 files
> (check archiving is needed in lvm.conf).
>           {
>               "vg": [
>                   {"vg_name":"pve"},
>                   {"vg_name":"spam"},
>                   {"vg_name":"testvg"}
>               ]
>           }
>       ]
>   }
> 
> Dominik suggested that this very much looks like an LVM bug, so I'll
> check whether it still happens on latest upstream LVM and, if yes, file
> a bug report there.

yes, that definitely sounds like a bug. potentially they'd also be open
to switching the log level/target so that it ends up on STDERR at
least..

Re: [pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[Friedrich Weber]

On 12/01/2024 11:28, Fabian Grünbichler wrote:
>> The vgs message is printed to stdout, so we could do something like
>>
>> warn $line if !defined($size);
>>
>> ?
> 
> yep, that would be an option (warn+return ;))

Right, thanks. Thinking about this some more, printing a user-visible
warning sounds more sensible than suppressing the warning complete
(either by passing `-qq` or ignoring the line, as in the current patch).
I'll send a v2.
>> Another complication I forgot about: For that user, /etc/lvm/archive had
>> 800000 files amounting to >1GiB, which also slowed down `vgs -o vg_name`
>> considerably (to >10s), presumably because `vgs -o vg_name` read all
>> those files. But unexpectedly, as soon as `-o` included `pv_name` the
>> command was fast again, presumably because it does not do the reads. So
>> I was considering to modify `sub lvm_vgs` to always include `-o pv_name`
>> in the command (not only if $includepvs is true), but was unsure if the
>> edge case warranted this (somewhat weird) workaround.
> 
> that sounds weird ;)
Yeah, I think I won't implement this for now. If users wonder about the
long status update times of pvestatd, they will look into the journal
and, in v2, see the warnings about the large archive.

>> By the way, the message also causes `vgs` to print invalid JSON:
>>
>> # rm -f /etc/lvm/backup/spam ; vgs -o vg_name -q --reportformat json
>> 2>/dev/null
>>   {
>>       "report": [
>>   Consider pruning spam VG archive with more then 8 MiB in 8305 files
>> (check archiving is needed in lvm.conf).
>>           {
>>               "vg": [
>>                   {"vg_name":"pve"},
>>                   {"vg_name":"spam"},
>>                   {"vg_name":"testvg"}
>>               ]
>>           }
>>       ]
>>   }
>>
>> Dominik suggested that this very much looks like an LVM bug, so I'll
>> check whether it still happens on latest upstream LVM and, if yes, file
>> a bug report there.
> 
> yes, that definitely sounds like a bug. potentially they'd also be open
> to switching the log level/target so that it ends up on STDERR at
> least..

done: https://github.com/lvmteam/lvm2/issues/137

Re: [pve-devel] [PATCH storage] lvm: avoid warning due to human-readable text in vgs output

[Fiona Ebner]

Am 12.01.24 um 16:11 schrieb Friedrich Weber:
> On 12/01/2024 11:28, Fabian Grünbichler wrote:
>>> The vgs message is printed to stdout, so we could do something like
>>>
>>> warn $line if !defined($size);
>>>
>>> ?
>>
>> yep, that would be an option (warn+return ;))
> 
> Right, thanks. Thinking about this some more, printing a user-visible
> warning sounds more sensible than suppressing the warning complete
> (either by passing `-qq` or ignoring the line, as in the current patch).
> I'll send a v2.

If we go for the warn route, please prefix the line appropriately. This
is in a function rather deep down that's executed during various
different top-level operations, so it should be made clear where it
comes from.