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

["Fabian Grünbichler" <f.gruenbichler@proxmox.com>]

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