From 4fcbbdee7bf19452076da80755062d4947130b01 Mon Sep 17 00:00:00 2001 From: David Teigland Date: Wed, 24 Mar 2021 14:19:54 -0500 Subject: [PATCH 05/10] 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 488337d..70926b7 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 0f97a16..4250d13 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 b22baaa..980fce6 100644 --- a/lib/config/config_settings.h +++ b/lib/config/config_settings.h @@ -876,6 +876,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 #include #include +#include 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= would write this info to the file. + * + * TODO: log/debug_to_file= would write full debugging to the file. + * (the same effect as log/file= 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 b723745..c807e59 100644 --- a/tools/args.h +++ b/tools/args.h @@ -318,6 +318,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 c1f049a..5ce6556 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 bf1dad2..dc00a05 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