Merge pull request systemd#23351 from keszybz/logind-message

logind: fix crash in logind on bad message string
evverx · May 11, 2022 · 34f6ae2 · 34f6ae2
2 parents 0cfb00d + 011a03a
commit 34f6ae2
Show file tree

Hide file tree

Showing 19 changed files with 86 additions and 61 deletions.
diff --git a/meson.build b/meson.build
@@ -33,6 +33,13 @@ conf.set_quoted('RELATIVE_SOURCE_PATH', relative_source_path)
 
 conf.set10('BUILD_MODE_DEVELOPER', get_option('mode') == 'developer',
            description : 'tailor build to development or release builds')
+verification = get_option('log-message-verification')
+if verification == 'auto'
+        verification = conf.get('BUILD_MODE_DEVELOPER') == 1
+else
+        verification = verification == 'true'
+endif
+conf.set10('LOG_MESSAGE_VERIFICATION', verification)
 
 want_ossfuzz = get_option('oss-fuzz')
 want_libfuzzer = get_option('llvm-fuzz')

diff --git a/meson_options.txt b/meson_options.txt
@@ -470,6 +470,8 @@ option('fuzz-tests', type : 'boolean', value : 'false',
        description : 'run the fuzzer regression tests by default (with sanitizers)')
 option('install-tests', type : 'boolean', value : 'false',
        description : 'install test executables')
+option('log-message-verification', type : 'combo', choices : ['auto', 'true', 'false'],
+       description : 'do fake printf() calls to verify format strings')
 
 option('ok-color', type : 'combo',
        choices : ['black', 'red', 'green', 'yellow', 'blue', 'magenta', 'cyan',

diff --git a/src/basic/log.c b/src/basic/log.c
@@ -67,6 +67,10 @@ static bool prohibit_ipc = false;
  * use here. */
 static char *log_abort_msg = NULL;
 
+#if LOG_MESSAGE_VERIFICATION || defined(__COVERITY__)
+bool _log_message_dummy = false; /* Always false */
+#endif
+
 /* An assert to use in logging functions that does not call recursively
  * into our logging functions (since that might lead to a loop). */
 #define assert_raw(expr)                                                \

diff --git a/src/basic/log.h b/src/basic/log.h
@@ -298,8 +298,16 @@ int log_emergency_level(void);
 
 bool log_on_console(void) _pure_;
 
-/* Helper to prepare various field for structured logging */
-#define LOG_MESSAGE(fmt, ...) "MESSAGE=" fmt, ##__VA_ARGS__
+/* Helper to wrap the main message in structured logging. The macro doesn't do much,
+ * except to provide visual grouping of the format string and its arguments. */
+#if LOG_MESSAGE_VERIFICATION || defined(__COVERITY__)
+/* Do a fake formatting of the message string to let the scanner verify the arguments against the format
+ * message. The variable will never be set to true, but we don't tell the compiler that :) */
+extern bool _log_message_dummy;
+#  define LOG_MESSAGE(fmt, ...) "MESSAGE=%.0d" fmt, (_log_message_dummy && printf(fmt, ##__VA_ARGS__)), ##__VA_ARGS__
+#else
+#  define LOG_MESSAGE(fmt, ...) "MESSAGE=" fmt, ##__VA_ARGS__
+#endif
 
 void log_received_signal(int level, const struct signalfd_siginfo *si);
 

diff --git a/src/basic/user-util.c b/src/basic/user-util.c
@@ -794,7 +794,7 @@ bool valid_user_group_name(const char *u, ValidUserFlags flags) {
                 /* Compare with strict result and warn if result doesn't match */
                 if (FLAGS_SET(flags, VALID_USER_WARN) && !valid_user_group_name(u, 0))
                         log_struct(LOG_NOTICE,
-                                   "MESSAGE=Accepting user/group name '%s', which does not match strict user/group name rules.", u,
+                                   LOG_MESSAGE("Accepting user/group name '%s', which does not match strict user/group name rules.", u),
                                    "USER_GROUP_NAME=%s", u,
                                    "MESSAGE_ID=" SD_MESSAGE_UNSAFE_USER_NAME_STR);
 

diff --git a/src/core/device.c b/src/core/device.c
@@ -493,7 +493,8 @@ static int device_setup_unit(Manager *m, sd_device *dev, const char *path, bool
                                 LOG_WARNING, r,
                                 "MESSAGE_ID=" SD_MESSAGE_DEVICE_PATH_NOT_SUITABLE_STR,
                                 "DEVICE=%s", path,
-                                LOG_MESSAGE("Failed to generate valid unit name from device path '%s', ignoring device: %m", path));
+                                LOG_MESSAGE("Failed to generate valid unit name from device path '%s', ignoring device: %m",
+                                            path));
 
         u = manager_get_unit(m, e);
         if (u) {

diff --git a/src/core/job.c b/src/core/job.c
@@ -716,8 +716,8 @@ static void job_emit_done_message(Unit *u, uint32_t job_id, JobType t, JobResult
                                 log_unit_struct(
                                         u,
                                         job_done_messages[result].log_level,
-                                        "MESSAGE=%s was skipped because all trigger condition checks failed.",
-                                        ident,
+                                        LOG_MESSAGE("%s was skipped because all trigger condition checks failed.",
+                                                    ident),
                                         "JOB_ID=%" PRIu32, job_id,
                                         "JOB_TYPE=%s", job_type_to_string(t),
                                         "JOB_RESULT=%s", job_result_to_string(result),
@@ -727,11 +727,11 @@ static void job_emit_done_message(Unit *u, uint32_t job_id, JobType t, JobResult
                                 log_unit_struct(
                                         u,
                                         job_done_messages[result].log_level,
-                                        "MESSAGE=%s was skipped because of a failed condition check (%s=%s%s).",
-                                        ident,
-                                        condition_type_to_string(c->type),
-                                        c->negate ? "!" : "",
-                                        c->parameter,
+                                        LOG_MESSAGE("%s was skipped because of a failed condition check (%s=%s%s).",
+                                                    ident,
+                                                    condition_type_to_string(c->type),
+                                                    c->negate ? "!" : "",
+                                                    c->parameter),
                                         "JOB_ID=%" PRIu32, job_id,
                                         "JOB_TYPE=%s", job_type_to_string(t),
                                         "JOB_RESULT=%s", job_result_to_string(result),

diff --git a/src/core/service.c b/src/core/service.c
@@ -2365,7 +2365,8 @@ static void service_enter_restart(Service *s) {
         log_unit_struct(UNIT(s), LOG_INFO,
                         "MESSAGE_ID=" SD_MESSAGE_UNIT_RESTART_SCHEDULED_STR,
                         LOG_UNIT_INVOCATION_ID(UNIT(s)),
-                        LOG_UNIT_MESSAGE(UNIT(s), "Scheduled restart job, restart counter is at %u.", s->n_restarts),
+                        LOG_UNIT_MESSAGE(UNIT(s),
+                                         "Scheduled restart job, restart counter is at %u.", s->n_restarts),
                         "N_RESTARTS=%u", s->n_restarts);
 
         /* Notify clients about changed restart counter */

diff --git a/src/core/transaction.c b/src/core/transaction.c
@@ -390,19 +390,20 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi
                 STRV_FOREACH_PAIR(unit_id, job_type, array)
                         /* logging for j not k here to provide a consistent narrative */
                         log_struct(LOG_WARNING,
-                                   "MESSAGE=%s: Found %s on %s/%s",
-                                   j->unit->id,
-                                   unit_id == array ? "ordering cycle" : "dependency",
-                                   *unit_id, *job_type,
+                                   LOG_UNIT_MESSAGE(j->unit,
+                                                    "Found %s on %s/%s",
+                                                    unit_id == array ? "ordering cycle" : "dependency",
+                                                    *unit_id, *job_type),
                                    "%s", unit_ids);
 
                 if (delete) {
                         const char *status;
                         /* logging for j not k here to provide a consistent narrative */
                         log_struct(LOG_ERR,
-                                   "MESSAGE=%s: Job %s/%s deleted to break ordering cycle starting with %s/%s",
-                                   j->unit->id, delete->unit->id, job_type_to_string(delete->type),
-                                   j->unit->id, job_type_to_string(j->type),
+                                   LOG_UNIT_MESSAGE(j->unit,
+                                                    "Job %s/%s deleted to break ordering cycle starting with %s/%s",
+                                                    delete->unit->id, job_type_to_string(delete->type),
+                                                    j->unit->id, job_type_to_string(j->type)),
                                    "%s", unit_ids);
 
                         if (log_get_show_color())
@@ -420,8 +421,8 @@ static int transaction_verify_order_one(Transaction *tr, Job *j, Job *from, unsi
                 }
 
                 log_struct(LOG_ERR,
-                           "MESSAGE=%s: Unable to break cycle starting with %s/%s",
-                           j->unit->id, j->unit->id, job_type_to_string(j->type),
+                           LOG_UNIT_MESSAGE(j->unit, "Unable to break cycle starting with %s/%s",
+                                            j->unit->id, job_type_to_string(j->type)),
                            "%s", unit_ids);
 
                 return sd_bus_error_setf(e, BUS_ERROR_TRANSACTION_ORDER_IS_CYCLIC,

diff --git a/src/core/unit.h b/src/core/unit.h
@@ -1046,7 +1046,8 @@ Condition *unit_find_failed_condition(Unit *u);
 
 #define log_unit_struct_iovec(unit, level, iovec, n_iovec) log_unit_struct_iovec_errno(unit, level, 0, iovec, n_iovec)
 
-#define LOG_UNIT_MESSAGE(unit, fmt, ...) "MESSAGE=%s: " fmt, (unit)->id, ##__VA_ARGS__
+/* Like LOG_MESSAGE(), but with the unit name prefixed. */
+#define LOG_UNIT_MESSAGE(unit, fmt, ...) LOG_MESSAGE("%s: " fmt, (unit)->id, ##__VA_ARGS__)
 #define LOG_UNIT_ID(unit) (unit)->manager->unit_log_format_string, (unit)->id
 #define LOG_UNIT_INVOCATION_ID(unit) (unit)->manager->invocation_log_format_string, (unit)->invocation_id_string
 

diff --git a/src/login/logind-action.c b/src/login/logind-action.c
@@ -29,7 +29,7 @@ static const HandleActionData handle_action_data_table[_HANDLE_ACTION_MAX] = {
                 .sleep_operation                 = _SLEEP_OPERATION_INVALID,
                 .message_id                      = SD_MESSAGE_SHUTDOWN_STR,
                 .message                         = "System is powering down",
-                .log_message                     = "power-off",
+                .log_verb                        = "power-off",
         },
         [HANDLE_REBOOT] = {
                 .handle                          = HANDLE_REBOOT,
@@ -41,7 +41,7 @@ static const HandleActionData handle_action_data_table[_HANDLE_ACTION_MAX] = {
                 .sleep_operation                 = _SLEEP_OPERATION_INVALID,
                 .message_id                      = SD_MESSAGE_SHUTDOWN_STR,
                 .message                         = "System is rebooting",
-                .log_message                     = "reboot",
+                .log_verb                        = "reboot",
         },
         [HANDLE_HALT] = {
                 .handle                          = HANDLE_HALT,
@@ -53,7 +53,7 @@ static const HandleActionData handle_action_data_table[_HANDLE_ACTION_MAX] = {
                 .sleep_operation                 = _SLEEP_OPERATION_INVALID,
                 .message_id                      = SD_MESSAGE_SHUTDOWN_STR,
                 .message                         = "System is halting",
-                .log_message                     = "halt",
+                .log_verb                        = "halt",
         },
         [HANDLE_KEXEC] = {
                 .handle                          = HANDLE_KEXEC,
@@ -65,7 +65,7 @@ static const HandleActionData handle_action_data_table[_HANDLE_ACTION_MAX] = {
                 .sleep_operation                 = _SLEEP_OPERATION_INVALID,
                 .message_id                      = SD_MESSAGE_SHUTDOWN_STR,
                 .message                         = "System is rebooting with kexec",
-                .log_message                     = "kexec",
+                .log_verb                        = "kexec",
         },
         [HANDLE_SUSPEND] = {
                 .handle                          = HANDLE_SUSPEND,

diff --git a/src/login/logind-action.h b/src/login/logind-action.h
@@ -39,7 +39,7 @@ struct HandleActionData {
         SleepOperation sleep_operation;
         const char* message_id;
         const char* message;
-        const char* log_message;
+        const char* log_verb;
 };
 
 int manager_handle_action(

diff --git a/src/login/logind-button.c b/src/login/logind-button.c
@@ -226,7 +226,8 @@ static int button_dispatch(sd_event_source *s, int fd, uint32_t revents, void *u
                                 log_debug("Power key pressed. Further action depends on the key press duration.");
                                 start_long_press(b->manager, &b->manager->power_key_long_press_event_source, long_press_of_power_key_handler);
                         } else {
-                                log_struct(LOG_INFO, LOG_MESSAGE("Power key pressed short."),
+                                log_struct(LOG_INFO,
+                                           LOG_MESSAGE("Power key pressed short."),
                                            "MESSAGE_ID=" SD_MESSAGE_POWER_KEY_STR);
                                 manager_handle_action(b->manager, INHIBIT_HANDLE_POWER_KEY, b->manager->handle_power_key, b->manager->power_key_ignore_inhibited, true);
                         }
@@ -242,7 +243,8 @@ static int button_dispatch(sd_event_source *s, int fd, uint32_t revents, void *u
                                 log_debug("Reboot key pressed. Further action depends on the key press duration.");
                                 start_long_press(b->manager, &b->manager->reboot_key_long_press_event_source, long_press_of_reboot_key_handler);
                         } else {
-                                log_struct(LOG_INFO, LOG_MESSAGE("Reboot key pressed short."),
+                                log_struct(LOG_INFO,
+                                           LOG_MESSAGE("Reboot key pressed short."),
                                            "MESSAGE_ID=" SD_MESSAGE_REBOOT_KEY_STR);
                                 manager_handle_action(b->manager, INHIBIT_HANDLE_REBOOT_KEY, b->manager->handle_reboot_key, b->manager->reboot_key_ignore_inhibited, true);
                         }
@@ -259,7 +261,8 @@ static int button_dispatch(sd_event_source *s, int fd, uint32_t revents, void *u
                                 log_debug("Suspend key pressed. Further action depends on the key press duration.");
                                 start_long_press(b->manager, &b->manager->suspend_key_long_press_event_source, long_press_of_suspend_key_handler);
                         } else {
-                                log_struct(LOG_INFO, LOG_MESSAGE("Suspend key pressed short."),
+                                log_struct(LOG_INFO,
+                                           LOG_MESSAGE("Suspend key pressed short."),
                                            "MESSAGE_ID=" SD_MESSAGE_SUSPEND_KEY_STR);
                                 manager_handle_action(b->manager, INHIBIT_HANDLE_SUSPEND_KEY, b->manager->handle_suspend_key, b->manager->suspend_key_ignore_inhibited, true);
                         }
@@ -270,7 +273,8 @@ static int button_dispatch(sd_event_source *s, int fd, uint32_t revents, void *u
                                 log_debug("Hibernate key pressed. Further action depends on the key press duration.");
                                 start_long_press(b->manager, &b->manager->hibernate_key_long_press_event_source, long_press_of_hibernate_key_handler);
                         } else {
-                                log_struct(LOG_INFO, LOG_MESSAGE("Hibernate key pressed short."),
+                                log_struct(LOG_INFO,
+                                           LOG_MESSAGE("Hibernate key pressed short."),
                                            "MESSAGE_ID=" SD_MESSAGE_HIBERNATE_KEY_STR);
                                 manager_handle_action(b->manager, INHIBIT_HANDLE_HIBERNATE_KEY, b->manager->handle_hibernate_key, b->manager->hibernate_key_ignore_inhibited, true);
                         }

diff --git a/src/login/logind-dbus.c b/src/login/logind-dbus.c
@@ -1515,32 +1515,20 @@ static int have_multiple_sessions(
 static int bus_manager_log_shutdown(
                 Manager *m,
                 const HandleActionData *a) {
-
-        const char *message, *log_message;
-
         assert(m);
         assert(a);
 
-        message = a->message;
-        log_message = a->log_message;
-
-        if (message)
-                message = strjoina("MESSAGE=", message);
-        else
-                message = "MESSAGE=System is shutting down";
-
-        if (isempty(m->wall_message))
-                message = strjoina(message, ".");
-        else
-                message = strjoina(message, " (", m->wall_message, ").");
-
-        if (log_message)
-                log_message = strjoina("SHUTDOWN=", log_message);
+        const char *message = a->message ?: "System is shutting down";
+        const char *log_verb = a->log_verb ? strjoina("SHUTDOWN=", a->log_verb) : NULL;
 
         return log_struct(LOG_NOTICE,
-                        "MESSAGE_ID=%s", a->message_id ? a->message_id : SD_MESSAGE_SHUTDOWN_STR,
-                        message,
-                        log_message);
+                          "MESSAGE_ID=%s", a->message_id ?: SD_MESSAGE_SHUTDOWN_STR,
+                          LOG_MESSAGE("%s%s%s%s.",
+                                      message,
+                                      m->wall_message ? " (" : "",
+                                      strempty(m->wall_message),
+                                      m->wall_message ? ")" : ""),
+                          log_verb);
 }
 
 static int lid_switch_ignore_handler(sd_event_source *e, uint64_t usec, void *userdata) {

diff --git a/src/resolve/resolved-dns-server.c b/src/resolve/resolved-dns-server.c
@@ -726,7 +726,8 @@ void dns_server_warn_downgrade(DnsServer *server) {
 
         log_struct(LOG_NOTICE,
                    "MESSAGE_ID=" SD_MESSAGE_DNSSEC_DOWNGRADE_STR,
-                   LOG_MESSAGE("Server %s does not support DNSSEC, downgrading to non-DNSSEC mode.", strna(dns_server_string_full(server))),
+                   LOG_MESSAGE("Server %s does not support DNSSEC, downgrading to non-DNSSEC mode.",
+                               strna(dns_server_string_full(server))),
                    "DNS_SERVER=%s", strna(dns_server_string_full(server)),
                    "DNS_SERVER_FEATURE_LEVEL=%s", dns_server_feature_level_to_string(server->possible_feature_level));
 

diff --git a/src/resolve/resolved-dns-transaction.c b/src/resolve/resolved-dns-transaction.c
@@ -394,7 +394,8 @@ void dns_transaction_complete(DnsTransaction *t, DnsTransactionState state) {
 
                 log_struct(LOG_NOTICE,
                            "MESSAGE_ID=" SD_MESSAGE_DNSSEC_FAILURE_STR,
-                           LOG_MESSAGE("DNSSEC validation failed for question %s: %s", key_str, dnssec_result_to_string(t->answer_dnssec_result)),
+                           LOG_MESSAGE("DNSSEC validation failed for question %s: %s",
+                                       key_str, dnssec_result_to_string(t->answer_dnssec_result)),
                            "DNS_TRANSACTION=%" PRIu16, t->id,
                            "DNS_QUESTION=%s", key_str,
                            "DNSSEC_RESULT=%s", dnssec_result_to_string(t->answer_dnssec_result),