From 0621739db9b751c48b8e7a6d67941aeca9fa2154 Mon Sep 17 00:00:00 2001

From: David Teigland <teigland@redhat.com>

Date: Wed, 24 Mar 2021 14:19:54 -0500

Subject: [PATCH 05/11] logging: to the systemd journal

Configure via lvm.conf log/journal or command line --journal.

Possible values:

"command" records command information.

"output" records default command output.

"debug" records full command debugging.

Multiple values can be set in lvm.conf as an array.

One value can be set in --journal which is added to

values set in lvm.conf

---

 lib/commands/toolcontext.c   | 30 +++++++++++++++

 lib/commands/toolcontext.h   |  1 +

 lib/config/config_settings.h |  6 +++

 lib/log/log.c                | 91 ++++++++++++++++++++++++++++++++++++++++++++

 lib/log/log.h                |  4 ++

 lib/log/lvm-logging.h        |  6 +++

 tools/args.h                 |  8 ++++

 tools/command-lines.in       |  2 +-

 tools/lvmcmdline.c           | 12 ++++++

 9 files changed, 159 insertions(+), 1 deletion(-)

diff --git a/lib/commands/toolcontext.c b/lib/commands/toolcontext.c

index 8991aeb..f939c3e 100644

--- a/lib/commands/toolcontext.c

+++ b/lib/commands/toolcontext.c

@@ -340,6 +340,33 @@ static int _parse_debug_classes(struct cmd_context *cmd)

 	return debug_classes;

 }

+static uint32_t _parse_log_journal(struct cmd_context *cmd, int cfg, const char *cfgname)

+{

+	const struct dm_config_node *cn;

+	const struct dm_config_value *cv;

+	uint32_t fields = 0;

+	uint32_t val;

+

+	if (!(cn = find_config_tree_array(cmd, cfg, NULL))) {

+		log_debug("Unable to find configuration for log/%s.", cfgname);

+		return 0;

+	}

+

+	for (cv = cn->v; cv; cv = cv->next) {

+		if (cv->type != DM_CFG_STRING) {

+			log_verbose("log/%s contains a value which is not a string.  Ignoring.", cfgname);

+			continue;

+		}

+

+		if ((val = log_journal_str_to_val(cv->v.str)))

+			fields |= val;

+		else

+			log_verbose("Unrecognised value for log/%s: %s", cfgname, cv->v.str);

+	}

+

+	return fields;

+}

+

 static void _init_logging(struct cmd_context *cmd)

 {

 	int append = 1;

@@ -408,6 +435,9 @@ static void _init_logging(struct cmd_context *cmd)

 	init_debug_file_fields(_parse_debug_fields(cmd, log_debug_file_fields_CFG, "debug_file_fields"));

 	init_debug_output_fields(_parse_debug_fields(cmd, log_debug_output_fields_CFG, "debug_output_fields"));

+	cmd->default_settings.journal = _parse_log_journal(cmd, log_journal_CFG, "journal");

+	init_log_journal(cmd->default_settings.journal);

+

 	t = time(NULL);

 	ctime_r(&t, &timebuf[0]);

 	timebuf[24] = '\0';

diff --git a/lib/commands/toolcontext.h b/lib/commands/toolcontext.h

index 0cb4ad7..2ee6524 100644

--- a/lib/commands/toolcontext.h

+++ b/lib/commands/toolcontext.h

@@ -41,6 +41,7 @@ struct config_info {

 	int udev_sync;

 	int udev_fallback;

 	int issue_discards;

+	uint32_t journal;

 	const char *msg_prefix;

 	const char *fmt_name;

 	const char *dmeventd_executable;

diff --git a/lib/config/config_settings.h b/lib/config/config_settings.h

index 76ebc10..63569bf 100644

--- a/lib/config/config_settings.h

+++ b/lib/config/config_settings.h

@@ -871,6 +871,12 @@ cfg(log_syslog_CFG, "syslog", log_CFG_SECTION, CFG_DEFAULT_COMMENTED, CFG_TYPE_B

 cfg(log_file_CFG, "file", log_CFG_SECTION, CFG_DEFAULT_UNDEFINED, CFG_TYPE_STRING, NULL, vsn(1, 0, 0), NULL, 0, NULL,

 	"Write error and debug log messages to a file specified here.\n")

+cfg_array(log_journal_CFG, "journal", log_CFG_SECTION, CFG_ALLOW_EMPTY | CFG_DEFAULT_COMMENTED, CFG_TYPE_STRING, NULL, vsn(2, 3, 12), NULL, 0, NULL,

+	  "Record lvm information in the systemd journal.\n"

+	  "command: record commands that are run.\n"

+	  "output: record default output from commands.\n"

+	  "debug: record debug messages from commands.\n")

+

 cfg(log_overwrite_CFG, "overwrite", log_CFG_SECTION, CFG_DEFAULT_COMMENTED, CFG_TYPE_BOOL, DEFAULT_OVERWRITE, vsn(1, 0, 0), NULL, 0, NULL,

 	"Overwrite the log file each time the program is run.\n")

diff --git a/lib/log/log.c b/lib/log/log.c

index 53ff5b1..8ebbf94 100644

--- a/lib/log/log.c

+++ b/lib/log/log.c

@@ -25,6 +25,7 @@

 #include <syslog.h>

 #include <ctype.h>

 #include <time.h>

+#include <systemd/sd-journal.h>

 static FILE *_log_file;

 static char _log_file_path[PATH_MAX];

@@ -40,6 +41,7 @@ static char _msg_prefix[30] = "  ";

 static int _abort_on_internal_errors_config = 0;

 static uint32_t _debug_file_fields;

 static uint32_t _debug_output_fields;

+static uint32_t _log_journal = 0;

 static lvm2_log_fn_t _lvm2_log_fn = NULL;

@@ -455,6 +457,11 @@ void init_debug_output_fields(uint32_t debug_fields)

 	_debug_output_fields = debug_fields;

 }

+void init_log_journal(uint32_t fields)

+{

+	_log_journal = fields;

+}

+

 static void _set_time_prefix(char *prefix, int buflen)

 {

@@ -609,6 +616,33 @@ static void _vprint_log(int level, const char *file, int line, int dm_errno_or_c

 	}

       log_it:

+

+	if (_log_journal) {

+		int to_journal = 0;

+

+		/* By default the visible command output is _LOG_WARN or less. */

+

+		if (_log_journal & LOG_JOURNAL_DEBUG)

+			to_journal = 1;

+		if ((_log_journal & LOG_JOURNAL_OUTPUT) && (log_level(level) <= _LOG_WARN))

+			to_journal = 1;

+

+		if (to_journal) {

+			int prio;

+			switch (log_level(level)) {

+			case _LOG_ERR:    prio = LOG_ERR; break;

+			case _LOG_WARN:   prio = LOG_WARNING; break;

+			case _LOG_INFO:   prio = LOG_INFO; break;

+			case _LOG_NOTICE: prio = LOG_NOTICE; break;

+			case _LOG_DEBUG:  prio = LOG_DEBUG; break;

+			default:          prio = LOG_INFO;

+			}

+			va_copy(ap, orig_ap);

+			sd_journal_printv(prio, trformat, ap);

+			va_end(ap);

+		}

+	}

+

 	if (!logged_via_report && ((verbose_level() >= level) && !_log_suppress)) {

 		if (verbose_level() > _LOG_DEBUG) {

 			memset(buf, 0, sizeof(buf));

@@ -792,3 +826,60 @@ void log_set_report_object_name_and_id(const char *name, const char *id)

 	_log_report.object_name = name;

 	_log_report.object_id = id;

 }

+

+/*

+ * TODO: log/journal=["daemon_command"]

+ *       daemon_command: record commands that are run by an lvm daemon.

+ *       (i.e. not commands run directly by a user.)

+ *       For this we need to be able to clearly identify when a command is

+ *       being run by dmeventd/lvmpolld/lvmdbusd.

+ *

+ * TODO: log/journal_commmand_names=["lvcreate","lvconvert"]

+ * This would restrict log/journal=["command"] to the listed command names.

+ * Also allow "!command" to exclude a command, e.g. ["!pvs"]

+ *

+ * TODO: log/journal_daemon_command_names=["lvcreate","lvconvert"]

+ * This would restrict log/journal=["dameon_command"] to the listed command names.

+ *

+ * TODO: log/journal_daemon_names=["dmeventd"]

+ * This would restrict log/journal=["daemon_command"] to commands run by

+ * the named daemon.

+ *

+ * TODO: log/command_to_file=<path> would write this info to the file.

+ *

+ * TODO: log/debug_to_file=<path> would write full debugging to the file.

+ *       (the same effect as log/file=<path> log/level=7)

+ */

+

+void log_command(const char *cmd_line, const char *cmd_name, const char *cmd_id)

+{

+	if (_log_journal & LOG_JOURNAL_COMMAND) {

+

+		/*

+		 * TODO: DAEMON=dmeventd|lvmpolld|lvmdbusd,

+		 * Could we include caller info such as libblkid, udev rule, etc?

+		 * Does systemd already record the caller for us?

+		 */

+

+		/* The command line, pid, and other things are automatically included. */

+

+		sd_journal_send("MESSAGE=lvm command %s", cmd_name,

+				"MESSAGE_ID=3ca432788c374e4ba684b834188eca36",

+				"LVM_CMD_NAME=%s", cmd_name,

+				"LVM_CMD_ID=%s", cmd_id,

+				"PRIORITY=%i", LOG_INFO,

+				NULL);

+	}

+}

+

+uint32_t log_journal_str_to_val(const char *str)

+{

+	if (!strcasecmp(str, "command"))

+		return LOG_JOURNAL_COMMAND;

+	if (!strcasecmp(str, "output"))

+		return LOG_JOURNAL_OUTPUT;

+	if (!strcasecmp(str, "debug"))

+		return LOG_JOURNAL_DEBUG;

+	return 0;

+}

+

diff --git a/lib/log/log.h b/lib/log/log.h

index d3848a4..b5f05f2 100644

--- a/lib/log/log.h

+++ b/lib/log/log.h

@@ -63,6 +63,10 @@

 #define LOG_DEBUG_FIELD_FILELINE	0x0004

 #define LOG_DEBUG_FIELD_MESSAGE		0x0008

+#define LOG_JOURNAL_COMMAND             0x0001

+#define LOG_JOURNAL_OUTPUT              0x0002

+#define LOG_JOURNAL_DEBUG               0x0004

+

 /*

  * Classes available for debug log messages.

diff --git a/lib/log/lvm-logging.h b/lib/log/lvm-logging.h

index 39108fc..fb18a41 100644

--- a/lib/log/lvm-logging.h

+++ b/lib/log/lvm-logging.h

@@ -62,6 +62,12 @@ void reset_log_duplicated(void);

 void init_syslog(int facility);

 void fin_syslog(void);

+void init_log_journal(uint32_t fields);

+uint32_t log_journal_str_to_val(const char *str);

+

+void log_command(const char *cmd_line, const char *cmd_name, const char *cmd_id);

+

+

 int error_message_produced(void);

 void reset_lvm_errno(int store_errmsg);

 int stored_errno(void);

diff --git a/tools/args.h b/tools/args.h

index 9aeec40..71db7f5 100644

--- a/tools/args.h

+++ b/tools/args.h

@@ -323,6 +323,14 @@ arg(ignoreunsupported_ARG, '\0', "ignoreunsupported", 0, 0, 0,

 arg(importdevices_ARG, '\0', "importdevices", 0, 0, 0,

     "Add devices to the devices file.\n")

+arg(journal_ARG, '\0', "journal", string_VAL, 0, 0,

+    "Record information in the systemd journal.\n"

+    "This information is in addition to information\n"

+    "enabled by the lvm.conf log/journal setting.\n"

+    "command: record information about the command.\n"

+    "output: record the default command output.\n"

+    "debug: record full command debugging.\n")

+

 arg(labelsector_ARG, '\0', "labelsector", number_VAL, 0, 0,

     "By default the PV is labelled with an LVM2 identifier in its second\n"

     "sector (sector 1). This lets you use a different sector near the\n"

diff --git a/tools/command-lines.in b/tools/command-lines.in

index aa3e3d9..68374c0 100644

--- a/tools/command-lines.in

+++ b/tools/command-lines.in

@@ -204,7 +204,7 @@

 #

 OO_ALL: --commandprofile String, --config String, --debug,

 --driverloaded Bool, --help, --nolocking, --lockopt String, --longhelp, --profile String, --quiet,

---verbose, --version, --yes, --test, --devicesfile String, --devices PV

+--verbose, --version, --yes, --test, --devicesfile String, --devices PV, --journal String

 #

 # options for pvs, lvs, vgs, fullreport

diff --git a/tools/lvmcmdline.c b/tools/lvmcmdline.c

index 6ea5487..222cd5b 100644

--- a/tools/lvmcmdline.c

+++ b/tools/lvmcmdline.c

@@ -2016,6 +2016,8 @@ out:

 	log_debug("Recognised command %s (id %d / enum %d).",

 		  commands[best_i].command_id, best_i, commands[best_i].command_enum);

+	log_command(cmd->cmd_line, commands[best_i].name, commands[best_i].command_id);

+

 	return &commands[best_i];

 }

@@ -2404,6 +2406,15 @@ static void _get_current_output_settings_from_args(struct cmd_context *cmd)

 		cmd->current_settings.verbose = 0;

 		cmd->current_settings.silent = (arg_count(cmd, quiet_ARG) > 1) ? 1 : 0;

 	}

+

+	/*

+	 * default_settings.journal is already set from config and has already been

+	 * applied using init_log_journal().

+	 * current_settings have been set to default_settings.

+	 * now --journal value adds to current_settings.

+	 */

+	if (arg_is_set(cmd, journal_ARG))

+		cmd->current_settings.journal |= log_journal_str_to_val(arg_str_value(cmd, journal_ARG, ""));

 }

 static void _apply_current_output_settings(struct cmd_context *cmd)

@@ -2413,6 +2424,7 @@ static void _apply_current_output_settings(struct cmd_context *cmd)

 	init_debug_classes_logged(cmd->default_settings.debug_classes);

 	init_verbose(cmd->current_settings.verbose + VERBOSE_BASE_LEVEL);

 	init_silent(cmd->current_settings.silent);

+	init_log_journal(cmd->current_settings.journal);

 }

 static int _read_devices_list(struct cmd_context *cmd)

-- 

1.8.3.1