successful commands output invalid json (trailing comma) for default command_log_selection with --reportformat json

[lge]

With a successful command, command_log_selection="!(log_type=status && message=success)" filters the last (success) message, and we end up with invalid json (note the trailing comma separator).

# lvcreate --config 'log { report_command_log=1 }' --reportformat json -an -n demo -l 1 scratch
 {
      "log": [
{"log_seq_num":"5", "log_type":"print", "log_context":"processing", "log_object_type":"vg", "log_object_name":"scratch", "log_object_id":"...", "log_object_group":"", "log_object_group_id":"", "log_message":"Logical volume \"demo\" created.", "log_errno":"0", "log_ret_code":"0"},
      ]
  }

Workaround:

• order in reverse (log/command_log_sort="-log_seq_num"; it only hurt if we filter out the "last" row, no harm done filtering the "first" (in output order))
• or select everything (e.g. log/command_log_selection="log_seq_num>=0")
• or both

suggested fix:

In device_mapper/libdm-report.c:_output_as_columns(), currently the separator is appended after an object was shown, unless it happens to be the last row (if (rowh != last_row && !dm_pool_grow_object(rh->mem, JSON_SEPARATOR, 0)) ... goto bad;); but the last row may be filtered away (if (!_should_display_row(row)) continue;), leaving the trailing separator.

I suggest to instead prepend the separator, unless it is the first row to be shown:

diff --git a/device_mapper/libdm-report.c b/device_mapper/libdm-report.c
index c3bab4906..7332918d1 100644
--- a/device_mapper/libdm-report.c
+++ b/device_mapper/libdm-report.c
@@ -4816,8 +4816,8 @@ static int _output_as_columns(struct dm_report *rh)
 	struct dm_list *fh, *rowh, *ftmp, *rtmp;
 	struct row *row = NULL;
 	struct dm_report_field *field;
-	struct dm_list *last_row;
 	int do_field_delim;
+	bool need_json_separator = false;
 	char *line;
 
 	/* If headings not printed yet, calculate field widths and print them */
@@ -4825,7 +4825,6 @@ static int _output_as_columns(struct dm_report *rh)
 		_report_headings(rh);
 
 	/* Print and clear buffer */
-	last_row = dm_list_last(&rh->rows);
 	dm_list_iterate_safe(rowh, rtmp, &rh->rows) {
 		row = dm_list_item(rowh, struct row);
 
@@ -4838,6 +4837,11 @@ static int _output_as_columns(struct dm_report *rh)
 		}
 
 		if (_is_json_report(rh)) {
+			if (need_json_separator && !dm_pool_grow_object(rh->mem, JSON_SEPARATOR, 0)) {
+				log_error(UNABLE_TO_EXTEND_OUTPUT_LINE_MSG);
+				goto bad;
+			}
+			need_json_separator = true;
 			if (!dm_pool_grow_object(rh->mem, JSON_OBJECT_START, 0)) {
 				log_error(UNABLE_TO_EXTEND_OUTPUT_LINE_MSG);
 				goto bad;
@@ -4879,11 +4883,6 @@ static int _output_as_columns(struct dm_report *rh)
 				log_error(UNABLE_TO_EXTEND_OUTPUT_LINE_MSG);
 				goto bad;
 			}
-			if (rowh != last_row &&
-			    !dm_pool_grow_object(rh->mem, JSON_SEPARATOR, 0)) {
-				log_error(UNABLE_TO_EXTEND_OUTPUT_LINE_MSG);
-				goto bad;
-			}
 		}
 
 		if (!dm_pool_grow_object(rh->mem, "\0", 1)) {

Not even compile tested, but something like this should do it, though I'm unclear where the newlines are generated, so I suspect it will now look like below 🙂

[
{ "first":"row"}
,{"second":"row"}
]

To fix that, you may need to reverse iterate the list to find the last not filtered row, then do as you did before, and again use that to decide whether to show a separator or not.

Thanks,
Lars

[prajnoha]

Nice catch! Thanks for the report, I'll have a look...

[prajnoha]

At first, I was wondering why we don't see the issue with usual reports (like pvs, lvs, vgs...), but then I realized we use DM_REPORT_OUTPUT_MULTIPLE_TIMES for the log report so we can use different selection criteria on the same log report (this is useful in lvm shell). In that case, we keep the whole report in memory, including the lines that don't even pass current selection criteria. And so the "last row" may not be the same as "last displayed row".

Not even compile tested, but something like this should do it, though I'm unclear where the newlines are generated, so I suspect it will now look like below 🙂

[
{ "first":"row"}
,{"second":"row"}
]

The newlines are generated as part of the log_print here:

lvm2/device_mapper/libdm-report.c

Lines 4913 to 4919 in c36e012

	if (!dm_pool_grow_object(rh->mem, "\0", 1)) {
	log_error("dm_report: Unable to terminate output line");
	goto bad;
	}
	line = (char *) dm_pool_end_object(rh->mem);
	log_print("%*s", rh->group_item ? rh->group_item->group->indent + (int) strlen(line) : 0, line);

To fix that, you may need to reverse iterate the list to find the last not filtered row, then do as you did before, and again use that to decide whether to show a separator or not.

Yeah, that is probably better approach, considering how current code works. This should be now fixed with: c36e012