Bug 2022135

Nov  8 13:30:57 hayes-02 lvmdbusd[2722]: JSON=
Nov  8 13:30:57 hayes-02 lvmdbusd[2722]:  {
Nov  8 13:30:57 hayes-02 lvmdbusd[2722]:      "report": [
Nov  8 13:30:57 hayes-02 lvmdbusd[2722]:          {
Nov  8 13:30:57 hayes-02 lvmdbusd[2722]:  Consider prunning raid_sanity VG archive with more then 709 MiB in 4904 files (check archiving is needed in lvm.conf).
Nov  8 13:30:57 hayes-02 lvmdbusd[2722]:  Consider prunning raid_sanity VG archive with more then 709 MiB in 4905 files (check archiving is needed in lvm.conf).
...

lvm is outputting a log message in the middle of the JSON output.  These "Consider prunning ..." messages are being outputted to stdout.  Lvm when told to output JSON cannot print messages in the middle of the structured JSON output.  Please move this message and any others like it to stderr.

Yep - this message was added to inform users about somewhat 'unusual' setup where too large space is consumed by archives.

It's likely to be moved to 'WARNING' - but original I wanted to be just 'information'.

But this 'json' reporting is complicating this report in somewhat 'unexpected' way.

We may need to introduce logging which bypasses  'json'.

Does log/report_command_log=1 help? That should separate the log messages from the usual report.

log/report_command_log=1  doesn't seem to do anything helpful here, unless I'm missing something.


[root@hayes-01 ~]# lvcreate -n foobar1 -L 50M FG
  Rounding up size to full physical extent 52.00 MiB
  Consider pruning FG VG archive with more then 379 MiB in 1381 files (check archiving is needed in lvm.conf).
  Logical volume "foobar1" created.

[root@hayes-01 ~]# lvcreate -n foobar2 -L 50M FG
  Rounding up size to full physical extent 52.00 MiB
  Consider pruning FG VG archive with more then 380 MiB in 1382 files (check archiving is needed in lvm.conf).
  Logical volume "foobar2" created.

[root@hayes-01 ~]# lvcreate --config 'log {report_command_log = 1}' -n foobar3 -L 50M FG
  Command Log
  ===========
  Seq LogType Context    ObjType ObjName ObjID                                  ObjGrp  ObjGrpID Msg                                                                                                          Errno RetCode
    1 print   processing vg      FG      WzF688-Xsy9-QL8R-JOAM-42j8-enky-JRe6Tj                  Rounding up size to full physical extent 52.00 MiB                                                               0       0
    2 print   processing vg      FG      WzF688-Xsy9-QL8R-JOAM-42j8-enky-JRe6Tj                  Consider pruning FG VG archive with more then 380 MiB in 1383 files (check archiving is needed in lvm.conf).     0       0
    3 print   processing vg      FG      WzF688-Xsy9-QL8R-JOAM-42j8-enky-JRe6Tj                  Logical volume "foobar3" created.                                                                                0       0

[root@hayes-01 ~]# lvcreate --config 'log {report_command_log = 0}' -n foobar4 -L 50M FG
  Rounding up size to full physical extent 52.00 MiB
  Consider pruning FG VG archive with more then 381 MiB in 1384 files (check archiving is needed in lvm.conf).
  Logical volume "foobar4" created.

If you switch to JSON output (like "lvcreate --reportformat json --config 'log {report_command_log = 1}' -n foobar3 -L 50M FG"), then the command log will be in its own proper JSON section, not as plain text interleaved with other JSON output. Then lvmdbusd should be able to parse it properly as it'll be full JSON output.

(...so then the fix would be for lvmdbusd needs to call lvm commands with that report_command_log=1)

I've just noticed that we already include report_command_log=1 lvmdbusd.profile that lvmdbusd uses:

  log {                                                                                                                                   
          # lvmdbusd relies on command log report to inspect LVM command's execution status                                               
          report_command_log=1                                                                                                                                                                                                                                                                                                   
          # display only outermost LVM shell-related log that lvmdbusd inspects first after LVM command execution (it calls 'lastlog' for more detailed log afterwards if needed)
          command_log_selection="log_context=shell"                                                                                       
          command_log_cols="log_seq_num,log_type,log_context,log_object_type,log_object_name,log_object_id,log_object_group,log_object_group_id,log_message,log_errno,log_ret_code"
          command_log_sort="log_seq_num"                                                                                                  
  }

It seems the report_command_log is not applied through the config profile - a bug then. Will check further...

I got to this again after a while...

Trying this on command line with /etc/lvm/archive full of files to trigger the "Consider pruning..." message, it works as expected:

  # vgcfgrestore --yes vg
    Restored volume group vg.


  # LVM_COMMAND_PROFILE=lvmdbusd lvm fullreport
    {
        "report": [
        ... (complete JSON report without any messages interleaved)
        "log": [
        ]
    }

When I change the "command_log_selection" to "command_log_selection=all" in lvmdbusd.priofile to report full log, I get:

 # vgcfgrestore --yes vg
   Restored volume group vg.

  # LVM_COMMAND_PROFILE=lvmdbusd lvm fullreport
    {
       "report": [
            ... (complete JSON report without any messages interleaved)

       "log": [
          {"log_seq_num":"1", "log_type":"print", "log_context":"processing", "log_object_type":"vg", "log_object_name":"vg", "log_object_id":"mWuhgp-HWfp-9AfH-nnCD-wYNy-yXLT-bhCE7H", "log_object_group":"", "log_object_group_id":"", "log_message":"Consider pruning vg VG archive with more then 8 MiB in 10061 files (check archiving is needed in lvm.conf).", "log_errno":"0", "log_ret_code":"0"},
          {"log_seq_num":"2", "log_type":"print", "log_context":"processing", "log_object_type":"vg", "log_object_name":"vg", "log_object_id":"mWuhgp-HWfp-9AfH-nnCD-wYNy-yXLT-bhCE7H", "log_object_group":"", "log_object_group_id":"", "log_message":"Consider pruning vg VG archive with more then 8 MiB in 10062 files (check archiving is needed in lvm.conf).", "log_errno":"0", "log_ret_code":"0"},
            ...

Which means the "Consider pruning..." messages are properly reported in the "log" report and not interleaved without any JSON formatting.

However, if I check this inside systemctl status lvm2-lvmdbusd.profile, I can see the same issue as Corey hit. Now, I'm not quite sure what the issue is inside lvmdbusd then - it should be calling an equivalent to "LVM_COMMAND_PROFILE=lvmdbusd lvm fullreport" and so the report should end up correctly formatted as it is when running the lvm fullreport from command line. So something must be different there inside lvmdbusd...

(In reply to Peter Rajnoha from comment #9)
> However, if I check this inside systemctl status lvm2-lvmdbusd.profile, I
> can see the same issue as Corey hit. Now, I'm not quite sure what the issue
> is inside lvmdbusd then - it should be calling an equivalent to
> "LVM_COMMAND_PROFILE=lvmdbusd lvm fullreport" and so the report should end
> up correctly formatted as it is when running the lvm fullreport from command
> line. So something must be different there inside lvmdbusd...

I believe the problem is that when we are in fork & exec mode lvmdbusd isn't setting LVM_COMMAND_PROFILE=lvmdbusd.
Lvmdbusd does when we are using lvmshell.  I'll add this to my existing patch set.

OK, switching over to you then...

Correction posted upstream: https://sourceware.org/git/?p=lvm2.git;a=commit;h=a5e6947d74f7b88f7f0df4328a923ad82a970634

Marking this Verified:Tested in the latest rpms.

kernel-4.18.0-447.el8    BUILT: Thu Dec 22 12:57:53 CST 2022
lvm2-2.03.14-9.el8    BUILT: Thu Dec  8 10:40:55 CST 2022
lvm2-libs-2.03.14-9.el8    BUILT: Thu Dec  8 10:40:55 CST 2022


This scenario no longer causes the JSONDecodeError traceback when the 'Consider pruning' warnings are present.

[root@hayes-02 archive]# pwd
/etc/lvm/archive
[root@hayes-02 archive]# ls -lrt | wc -l
1559
[root@hayes-02 tmp]# ps -ef | grep lvmdbus
root        2847       1 37 16:03 ?        00:14:51 /usr/libexec/platform-python /usr/sbin/lvmdbusd


SCENARIO (raid1) - [recover_corrupt_mda_below_raid_w_no_restorefile]
Create a raid, corrupt its metadata and restore the volume using no backup file
Create a raid on hayes-02, corrupt its metadata, and then restore the volume using no backup file
hayes-02: lvcreate --yes  --nosync --type raid1 -m 1 -n corrupt_meta_raid -L 300M raid_sanity
  WARNING: New raid1 won't be synchronised. Don't read what you didn't write!
Corrupting PV /dev/sdc1 (used in this raid)
1000+0 records in
1000+0 records out
512000 bytes (512 kB, 500 KiB) copied, 0.0169215 s, 30.3 MB/s
Running vgck (bug 894136)
  WARNING: Couldn't find device with uuid 6COfwU-ReLn-6moA-XmLZ-kfdb-G2Ji-hUQle3.
  WARNING: VG raid_sanity is missing PV 6COfwU-ReLn-6moA-XmLZ-kfdb-G2Ji-hUQle3 (last written to /dev/sdc1).
  The volume group is missing 1 physical volumes.
Activating VG in partial readonly mode
vgchange -an --partial raid_sanity
  PARTIAL MODE. Incomplete logical volumes will be processed.
  WARNING: Couldn't find device with uuid 6COfwU-ReLn-6moA-XmLZ-kfdb-G2Ji-hUQle3.
  WARNING: VG raid_sanity is missing PV 6COfwU-ReLn-6moA-XmLZ-kfdb-G2Ji-hUQle3 (last written to /dev/sdc1).
Recreating PV using its old uuid
pvcreate -ff -y --norestorefile --uuid "6COfwU-ReLn-6moA-XmLZ-kfdb-G2Ji-hUQle3" /dev/sdc1
Restoring the VG back to its original state
vgcfgrestore --yes raid_sanity
Reactivating VG

Waiting until all mirror|raid volumes become fully syncd...
   1/1 mirror(s) are fully synced: ( 100.00% )
Sleeping 15 sec
perform raid rebuilding (lvchange --yes --rebuild /dev/sdc1 raid_sanity/corrupt_meta_raid)
rebuild attr:raid_sanity-corrupt_meta_raid: 0 614400 raid raid1 2 aA 231168/614400 recover 0 0 -

Waiting until all mirror|raid volumes become fully syncd...
   1/1 mirror(s) are fully synced: ( 100.00% )
Sleeping 15 sec

Deactivating raid corrupt_meta_raid... and removing


[root@hayes-02 tmp]# grep JSONDecodeError /var/log/messages
[root@hayes-02 tmp]#

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (lvm2 bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:3048