Thing here is that we differentiate two log contexts (the "log_context" field in the output):

  - "processing" (messages coming from the processing of the command itself)
  - "shell" (messages for the overall results of the commands as returned in the shell)

In the lvmdbusd.profile, we limit the log to show only the overall "shell" context, not the "processing" one:

  log {
    ...
    command_log_selection="log_context=shell"
    ...
  }

You can let lvm to report also the rest (the log messages belonging to "processing" context) by modifying this selection if needed. If you want all possible log messages to land in the output, you can use:

  log {
     command_log_selection="all"
  }

Then you should be able to see exactly what you see in the output of usual command, unfiltered. The "all" is a special keyword we use can use for -S|--select as well as --options|-o cmd line arg (I've just noticed that maybe we haven't documented this in the "man lvmreport" much, I'll add some notes there if it's missing...)

===

Another thing is that in this exact case, as in your example, where the device is excluded because it's not in devices file, it's actually not an error for the command as a whole (return code 0). So that's why you see "success" as overall result.

===

We could change the lvmdbusd.profile to also display the log messages from "processing" context, but that could be quite a long list if we're processing many PV/LVs/segments... So maybe we can try to come up with some other selection criteria which would still show us info we need but at the same time it wouldn't display too much (...that wouldn't be used in the end anyway and just eating resources).

(In reply to Peter Rajnoha from comment #1)
> Thing here is that we differentiate two log contexts (the "log_context"
> field in the output):
> 
>   - "processing" (messages coming from the processing of the command itself)
>   - "shell" (messages for the overall results of the commands as returned in
> the shell)
> 
> In the lvmdbusd.profile, we limit the log to show only the overall "shell"
> context, not the "processing" one:
> 
>   log {
>     ...
>     command_log_selection="log_context=shell"
>     ...
>   }
> 
> You can let lvm to report also the rest (the log messages belonging to
> "processing" context) by modifying this selection if needed. If you want all
> possible log messages to land in the output, you can use:
> 
>   log {
>      command_log_selection="all"
>   }
> 
> Then you should be able to see exactly what you see in the output of usual
> command, unfiltered. The "all" is a special keyword we use can use for
> -S|--select as well as --options|-o cmd line arg (I've just noticed that
> maybe we haven't documented this in the "man lvmreport" much, I'll add some
> notes there if it's missing...)

I just did an experiment changing the lvmdbusd profile to command_log_selection="all"

I still get no output of any kind

> ===
> 
> Another thing is that in this exact case, as in your example, where the
> device is excluded because it's not in devices file, it's actually not an
> error for the command as a whole (return code 0). So that's why you see
> "success" as overall result.

I see success when I issue it from the shell, from lvm shell when not using
the lvmdbusd profile I see
"Too many arguments, sorry."

Should I write a separate bug on this?
 
> ===
> 
> We could change the lvmdbusd.profile to also display the log messages from
> "processing" context, but that could be quite a long list if we're
> processing many PV/LVs/segments... So maybe we can try to come up with some
> other selection criteria which would still show us info we need but at the
> same time it wouldn't display too much (...that wouldn't be used in the end
> anyway and just eating resources).

As I mentioned above, the message "Too many arguments, sorry." doesn't show up
when using:

log {
      command_log_selection="all"
}

If a command completes without error we still need JSON output to know the command
completed (good or bad) when using the lvm shell with json.  We have no other indication that the
command has completed.  Otherwise we assume the command is still running.  The "lvm>"
prompt is missing when editline is compiled in.  Maybe we need to revisit that.

Ah, I wrongly understood the issue then! I thought "Too many arguments, sorry." is just your note to cut off too long input from the report (it looked a bit informal to be a message from LVM). This is coming from the outermost code handling cmd execution, I can see that the limit is:

                if (lvm_split(input, &argc, argv, MAX_ARGS) == MAX_ARGS) {                                                                                                                                                                                                                                                                                                                     
                        _discard_log_report_content(cmd);                                                                               
                        log_error("Too many arguments, sorry.");                                                                        
                        continue;                                                                                                       
                }        

Where MAX_ARGS is only 64 for some reason. I'll check if we could do better (also better from logging point of view - this outermost code is probably not covered by log report at all).

This is a one-line fix to include the error message in the output: https://sourceware.org/git/?p=lvm2.git;a=commit;h=2fa99164938d11221fe6afc30af4f016bbc02450

(The reason why it wasn't do so is in the commit message.)

The other question of why we use 64 for MAX_ARGS is a different topic - seems we use this limit since long time ago, I'm not sure about why this number was chosen exactly. If this is an issue, we can try to increase the limit...

Regarding the log report selection, just one more note: by default, the log report selection in lvmdbusd.profile is set to:

  "command_log_selection="log_context=shell"

This gives you overall result of the command execution, so you don't see any other messages (like the ones with "log_context=processing"). You can either set the command_log_selection="all" (in which case you will always see everything) OR alternatively, you can keep the command_log_selection="log_context=shell" and if it fails (or you just need more log about what was happening), you can ask for details with "lastlog" after the previous command finished.

I compiled a build locally to try this.  lvmdbusd always issues a "lastlog" to retrieve the error reason when we have a "log", there is no lastlog available for this error?


An example running 2 different failing pvcreate commands

# LVM_COMMAND_PROFILE=lvmdbusd  $LVM_BINARY
lvm> pvcreate /dev/sdk
  {
      "log": [
          {"log_seq_num":"2", "log_type":"status", "log_context":"shell", "log_object_type":"cmd", "log_object_name":"pvcreate", "log_object_id":"", "log_object_group":"", "log_object_group_id":"", "log_message":"failure", "log_errno":"0", "log_ret_code":"5"}
      ]
  }
lvm> lastlog
  {
      "log": [
          {"log_seq_num":"1", "log_type":"error", "log_context":"processing", "log_object_type":"cmd", "log_object_name":"pvcreate", "log_object_id":"", "log_object_group":"", "log_object_group_id":"", "log_message":"No device found for /dev/sdk.", "log_errno":"-1", "log_ret_code":"0"},
          {"log_seq_num":"2", "log_type":"status", "log_context":"shell", "log_object_type":"cmd", "log_object_name":"pvcreate", "log_object_id":"", "log_object_group":"", "log_object_group_id":"", "log_message":"failure", "log_errno":"0", "log_ret_code":"5"}
      ]
  }
lvm> pvscan --cache /dev/sda /dev/sda1 /dev/sda2 /dev/sda3 /dev/sdb /dev/sdc /dev/sdd /dev/sde /dev/sdf /dev/sdf1 /dev/sdf10 /dev/sdf11 /dev/sdf12 /dev/sdf13 /dev/sdf14 /dev/sdf15 /dev/sdf16 /dev/sdf17 /dev/sdf18 /dev/sdf19 /dev/sdf2 /dev/sdf20 /dev/sdf21 /dev/sdf22 /dev/sdf23 /dev/sdf24 /dev/sdf25 /dev/sdf26 /dev/sdf27 /dev/sdf28 /dev/sdf29 /dev/sdf3 /dev/sdf30 /dev/sdf31 /dev/sdf32 /dev/sdf33 /dev/sdf34 /dev/sdf35 /dev/sdf36 /dev/sdf37 /dev/sdf38 /dev/sdf39 /dev/sdf4 /dev/sdf40 /dev/sdf41 /dev/sdf42 /dev/sdf43 /dev/sdf44 /dev/sdf45 /dev/sdf46 /dev/sdf47 /dev/sdf48 /dev/sdf49 /dev/sdf5 /dev/sdf50 /dev/sdf51 /dev/sdf52 /dev/sdf53 /dev/sdf54 /dev/sdf55 /dev/sdf56 /dev/sdf57 /dev/sdf58 /dev/sdf59 /dev/sdf6 /dev/sdf60 /dev/sdf61 /dev/sdf62 /dev/sdf63 /dev/sdf64 /dev/sdf65 /dev/sdf66 /dev/sdf67 /dev/sdf68 /dev/sdf7 /dev/sdf8 /dev/sdf9
  {
      "log": [
          {"log_seq_num":"1", "log_type":"error", "log_context":"shell", "log_object_type":"cmd", "log_object_name":"", "log_object_id":"", "log_object_group":"", "log_object_group_id":"", "log_message":"Too many arguments, sorry.", "log_errno":"-1", "log_ret_code":"0"}
      ]
  }
lvm> lastlog
  {
  }
lvm> 



Also, why is the "log_ret_code":"0"

Created attachment 1905533 [details]
Add pre-cmd log report for lvm shell and use in lastlog

(In reply to Tony Asleson from comment #6)
> lvm> pvscan --cache /dev/sda /dev/sda1 /dev/sda2 /dev/sda3 /dev/sdb /dev/sdc
...
>   {
>       "log": [
>           {"log_seq_num":"1", "log_type":"error", "log_context":"shell",
> "log_object_type":"cmd", "log_object_name":"", "log_object_id":"",
> "log_object_group":"", "log_object_group_id":"", "log_message":"Too many
> arguments, sorry.", "log_errno":"-1", "log_ret_code":"0"}
>       ]
>   }
> lvm> lastlog
>   {
>   }

That's because lastlog was primarily supposed to report log from last command's execution. Here, we didn't even get to that - it's pre-cmd. But if we need lastlog even here, I can add that easily. Please, try the patch attached - it adds a new "pre-cmd" log report object type so we can also identify this in the lastlog.

> lvm> 
> 
> 
> 
> Also, why is the "log_ret_code":"0"

0 for failure.

I've also noticed that with the new "json_std" format, we need to report all the binary values as numeric (that means, we will force report/binary_values_as_numeric=1 with "json_std" format). All these values are internally marked as numeric (0 - enabled/on...; 1 - disable/off...; -1 - undefined). When printing in "json_std" format, the code automatically removes double quotes for such values then. In case we use descriptive synonyms (strings) instead of the numeric value, we'd end up with invalid json where strings are not quoted. This is clearly visible if you use lvm fullreport --reportformat json_std. I'll add one more patch for this...

I've put both patches here (the fix for json_std format vs. numeric values is actually addition for bug #2100126): https://sourceware.org/git/?p=lvm2.git;a=shortlog;h=refs/heads/dev-prajnoha-report-fixes

https://sourceware.org/git/?p=lvm2.git;a=commit;h=2fa99164938d11221fe6afc30af4f016bbc02450
https://sourceware.org/git/?p=lvm2.git;a=commit;h=508782a9135acf13b39b47605e675a5678495c58

Marking Verified:Tested (SanityOnly) with the latest rpms.

kernel-5.14.0-176.el9    BUILT: Wed Oct 12 03:57:18 AM CDT 2022
lvm2-2.03.17-1.el9    BUILT: Thu Nov 10 10:02:16 AM CST 2022
lvm2-libs-2.03.17-1.el9    BUILT: Thu Nov 10 10:02:16 AM CST 2022

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:2544