From 0cb09bcb825ab86ba4ca70be4e6322eaf9baee95 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sun, 8 May 2022 17:21:09 +0200 Subject: [PATCH 1/7] logind: fix crash in logind on user-specified message string This is trivially exploitable (in the sense of causing a crash from SEGV) e.g. by 'shutdown now "Message %s %s %n"'. The message is settable through polkit, but is limited to auth_admin: Set a wall message Authentication is required to set a wall message auth_admin_keep auth_admin_keep auth_admin_keep Bug introduced in 9ef15026c0e7e6600372056c43442c99ec53746e ('logind/systemctl: introduce SetWallMessage and --message', 2015-09-15). --- src/login/logind-dbus.c | 30 +++++++++--------------------- 1 file changed, 9 insertions(+), 21 deletions(-) diff --git a/src/login/logind-dbus.c b/src/login/logind-dbus.c index 914e56bd77..5c17d4ec04 100644 --- 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_message = a->log_message ? strjoina("SHUTDOWN=", a->log_message) : 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_message); } static int lid_switch_ignore_handler(sd_event_source *e, uint64_t usec, void *userdata) { From 153d1579ef5255e589cefab0cf149c55580a25a4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sun, 8 May 2022 17:51:42 +0200 Subject: [PATCH 2/7] logind: rename "log_message" to "log_verb" This field is used to log SHUTDOWN=. Calling it "something-message" is confusing. --- src/login/logind-action.c | 8 ++++---- src/login/logind-action.h | 2 +- src/login/logind-dbus.c | 4 ++-- 3 files changed, 7 insertions(+), 7 deletions(-) diff --git a/src/login/logind-action.c b/src/login/logind-action.c index 5a691307b3..6a873009bc 100644 --- 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 index 03284414c5..c891787e6c 100644 --- 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-dbus.c b/src/login/logind-dbus.c index 5c17d4ec04..f7cff58005 100644 --- a/src/login/logind-dbus.c +++ b/src/login/logind-dbus.c @@ -1519,7 +1519,7 @@ static int bus_manager_log_shutdown( assert(a); const char *message = a->message ?: "System is shutting down"; - const char *log_message = a->log_message ? strjoina("SHUTDOWN=", a->log_message) : NULL; + const char *log_verb = a->log_verb ? strjoina("SHUTDOWN=", a->log_verb) : NULL; return log_struct(LOG_NOTICE, "MESSAGE_ID=%s", a->message_id ?: SD_MESSAGE_SHUTDOWN_STR, @@ -1528,7 +1528,7 @@ static int bus_manager_log_shutdown( m->wall_message ? " (" : "", strempty(m->wall_message), m->wall_message ? ")" : ""), - log_message); + log_verb); } static int lid_switch_ignore_handler(sd_event_source *e, uint64_t usec, void *userdata) { From 92663a5e5beb44d91a5cdae56d1bc7cfce01fe0a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Tue, 10 May 2022 13:39:08 +0200 Subject: [PATCH 3/7] tree-wide: use LOG_MESSAGE() where possible Also break some long lines for more uniform formatting. No functional change. I went over all log_struct, log_struct_errno, log_unit_struct, log_unit_struct_errno calls, and they seem fine. --- src/basic/log.h | 3 ++- src/basic/user-util.c | 2 +- src/core/device.c | 3 ++- src/core/job.c | 14 +++++++------- src/core/service.c | 3 ++- src/login/logind-button.c | 12 ++++++++---- src/resolve/resolved-dns-server.c | 3 ++- src/resolve/resolved-dns-transaction.c | 3 ++- src/test/test-log.c | 15 ++++++++++----- src/timesync/timesyncd-manager.c | 3 ++- src/udev/udevadm-settle.c | 2 +- 11 files changed, 39 insertions(+), 24 deletions(-) diff --git a/src/basic/log.h b/src/basic/log.h index 0d927bfce9..6f0d838de3 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -298,7 +298,8 @@ int log_emergency_level(void); bool log_on_console(void) _pure_; -/* Helper to prepare various field for structured logging */ +/* 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. */ #define LOG_MESSAGE(fmt, ...) "MESSAGE=" fmt, ##__VA_ARGS__ 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 index da3b922bc9..8b1283a9ec 100644 --- 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 index f65dbfcb1e..feb6479361 100644 --- 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 index 94ab381626..36d6f0a456 100644 --- 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 index 2d7a086852..9f7af9dffb 100644 --- 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/login/logind-button.c b/src/login/logind-button.c index a2b43d3684..368a08a095 100644 --- 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/resolve/resolved-dns-server.c b/src/resolve/resolved-dns-server.c index 2ef2568dac..9b74a8d6d8 100644 --- 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 index cec3cea7c5..cd9cdeb783 100644 --- 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), diff --git a/src/test/test-log.c b/src/test/test-log.c index cf438e6869..ae3d073d82 100644 --- a/src/test/test-log.c +++ b/src/test/test-log.c @@ -31,16 +31,21 @@ static void test_log_struct(void) { "MESSAGE=Waldo PID="PID_FMT" (no errno)", getpid_cached(), "SERVICE=piepapo"); - log_struct_errno(LOG_INFO, EILSEQ, - "MESSAGE=Waldo PID="PID_FMT": %m (normal)", getpid_cached(), + /* The same as above, just using LOG_MESSAGE(), which is generally recommended */ + log_struct(LOG_INFO, + LOG_MESSAGE("Waldo PID="PID_FMT" (no errno)", getpid_cached()), "SERVICE=piepapo"); + log_struct_errno(LOG_INFO, EILSEQ, + LOG_MESSAGE("Waldo PID="PID_FMT": %m (normal)", getpid_cached()), + "SERVICE=piepapo"); + log_struct_errno(LOG_INFO, SYNTHETIC_ERRNO(EILSEQ), - "MESSAGE=Waldo PID="PID_FMT": %m (synthetic)", getpid_cached(), - "SERVICE=piepapo"); + LOG_MESSAGE("Waldo PID="PID_FMT": %m (synthetic)", getpid_cached()), + "SERVICE=piepapo"); log_struct(LOG_INFO, - "MESSAGE=Foobar PID="PID_FMT, getpid_cached(), + LOG_MESSAGE("Foobar PID="PID_FMT, getpid_cached()), "FORMAT_STR_TEST=1=%i A=%c 2=%hi 3=%li 4=%lli 1=%p foo=%s 2.5=%g 3.5=%g 4.5=%Lg", (int) 1, 'A', (short) 2, (long int) 3, (long long int) 4, (void*) 1, "foo", (float) 2.5f, (double) 3.5, (long double) 4.5, "SUFFIX=GOT IT"); diff --git a/src/timesync/timesyncd-manager.c b/src/timesync/timesyncd-manager.c index 78b9cb9932..9325523838 100644 --- a/src/timesync/timesyncd-manager.c +++ b/src/timesync/timesyncd-manager.c @@ -620,7 +620,8 @@ static int manager_receive_response(sd_event_source *source, int fd, uint32_t re m->synchronized = true; log_struct(LOG_INFO, - LOG_MESSAGE("Initial clock synchronization to %s.", FORMAT_TIMESTAMP_STYLE(dts.realtime, TIMESTAMP_US)), + LOG_MESSAGE("Initial clock synchronization to %s.", + FORMAT_TIMESTAMP_STYLE(dts.realtime, TIMESTAMP_US)), "MESSAGE_ID=" SD_MESSAGE_TIME_SYNC_STR, "MONOTONIC_USEC=" USEC_FMT, dts.monotonic, "REALTIME_USEC=" USEC_FMT, dts.realtime, diff --git a/src/udev/udevadm-settle.c b/src/udev/udevadm-settle.c index 6da9439bd2..df9fefc8d0 100644 --- a/src/udev/udevadm-settle.c +++ b/src/udev/udevadm-settle.c @@ -150,7 +150,7 @@ static int emit_deprecation_warning(void) { return -ENOMEM; log_struct(LOG_NOTICE, - "MESSAGE=systemd-udev-settle.service is deprecated. Please fix %s not to pull it in.", t, + LOG_MESSAGE("systemd-udev-settle.service is deprecated. Please fix %s not to pull it in.", t), "OFFENDING_UNITS=%s", t, "MESSAGE_ID=" SD_MESSAGE_SYSTEMD_UDEV_SETTLE_DEPRECATED_STR); } From f66020ab7f79b639f5ba985367245132344f2a72 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Wed, 11 May 2022 07:40:29 +0200 Subject: [PATCH 4/7] core: use LOG_UNIT_MESSAGE() where appropriate --- src/core/transaction.c | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/src/core/transaction.c b/src/core/transaction.c index 7bb8dfb0f4..bafbb80b47 100644 --- 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, From b9ce5cf9caf52503394ad5eac7a3dee2eee1a296 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Tue, 10 May 2022 14:11:55 +0200 Subject: [PATCH 5/7] Optionally call printf on LOG_MESSAGE() arguments MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit With an intentional mistake: ../src/login/logind-dbus.c: In function ‘bus_manager_log_shutdown’: ../src/login/logind-dbus.c:1542:39: error: format ‘%s’ expects a matching ‘char *’ argument [-Werror=format=] 1542 | LOG_MESSAGE("%s %s", message), | ^~~~~~~ --- meson.build | 1 + meson_options.txt | 2 ++ src/basic/log.h | 8 +++++++- src/core/unit.h | 3 ++- 4 files changed, 12 insertions(+), 2 deletions(-) diff --git a/meson.build b/meson.build index 051eea9aac..46f062d530 100644 --- a/meson.build +++ b/meson.build @@ -33,6 +33,7 @@ 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') +conf.set10('LOG_MESSAGE_VERIFICATION', get_option('log-message-verification')) want_ossfuzz = get_option('oss-fuzz') want_libfuzzer = get_option('llvm-fuzz') diff --git a/meson_options.txt b/meson_options.txt index 2a030ac28e..ff59120f77 100644 --- 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 : 'boolean', value : '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.h b/src/basic/log.h index 6f0d838de3..b03ca3ef21 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -300,7 +300,13 @@ bool log_on_console(void) _pure_; /* 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. */ -#define LOG_MESSAGE(fmt, ...) "MESSAGE=" fmt, ##__VA_ARGS__ +#if LOG_MESSAGE_VERIFICATION +/* Do a fake formatting of the message string to let the scanner verify the arguments + * against the format message. */ +# define LOG_MESSAGE(fmt, ...) "MESSAGE=%.0d" fmt, 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/core/unit.h b/src/core/unit.h index 733eeecd7f..20c511c108 100644 --- 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 From 1ec7c15613028c75cf160a56bec0642a99109551 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Tue, 10 May 2022 14:12:57 +0200 Subject: [PATCH 6/7] Do LOG_MESSAGE_VERIFICATION in coverity runs This should be enough to get reports if we screw up anywhere, coverity does analysis of printf format strings. --- src/basic/log.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/basic/log.h b/src/basic/log.h index b03ca3ef21..7b89c4df63 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -300,7 +300,7 @@ bool log_on_console(void) _pure_; /* 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 +#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. */ # define LOG_MESSAGE(fmt, ...) "MESSAGE=%.0d" fmt, printf(fmt, ##__VA_ARGS__), ##__VA_ARGS__ From 011a03a3fae25f2b715f2d88bc16b4cb8f8f2da2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Wed, 11 May 2022 16:42:13 +0200 Subject: [PATCH 7/7] meson: turn on log-message-verification by default in developer builds MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit I'm not _quite_ convinced that this a good idea… I'm at least keeping it separate to make it easy to revert ;) --- meson.build | 8 +++++++- meson_options.txt | 2 +- src/basic/log.c | 4 ++++ src/basic/log.h | 7 ++++--- 4 files changed, 16 insertions(+), 5 deletions(-) diff --git a/meson.build b/meson.build index 46f062d530..7d4233ca7f 100644 --- a/meson.build +++ b/meson.build @@ -33,7 +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') -conf.set10('LOG_MESSAGE_VERIFICATION', get_option('log-message-verification')) +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 index ff59120f77..26d1170c50 100644 --- a/meson_options.txt +++ b/meson_options.txt @@ -470,7 +470,7 @@ 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 : 'boolean', value : 'false', +option('log-message-verification', type : 'combo', choices : ['auto', 'true', 'false'], description : 'do fake printf() calls to verify format strings') option('ok-color', type : 'combo', diff --git a/src/basic/log.c b/src/basic/log.c index 12071e2ebd..8f36c1dfad 100644 --- 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 index 7b89c4df63..b7b0a42e49 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -301,9 +301,10 @@ bool log_on_console(void) _pure_; /* 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. */ -# define LOG_MESSAGE(fmt, ...) "MESSAGE=%.0d" fmt, printf(fmt, ##__VA_ARGS__), ##__VA_ARGS__ +/* 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