From d9cb4bba2037db946754c414023ede303288cae2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sun, 4 Aug 2019 11:06:33 +0200 Subject: [PATCH 1/3] timedated: minor code simplifications --- src/timedate/timedated.c | 27 +++++++++------------------ 1 file changed, 9 insertions(+), 18 deletions(-) diff --git a/src/timedate/timedated.c b/src/timedate/timedated.c index 074ba3c079..706e0ff448 100644 --- a/src/timedate/timedated.c +++ b/src/timedate/timedated.c @@ -272,31 +272,25 @@ static int context_read_data(Context *c) { static int context_write_data_timezone(Context *c) { _cleanup_free_ char *p = NULL; - int r = 0; assert(c); if (isempty(c->zone)) { if (unlink("/etc/localtime") < 0 && errno != ENOENT) - r = -errno; - - return r; + return -errno; + return 0; } p = path_join("../usr/share/zoneinfo", c->zone); if (!p) return log_oom(); - r = symlink_atomic(p, "/etc/localtime"); - if (r < 0) - return r; - - return 0; + return symlink_atomic(p, "/etc/localtime"); } static int context_write_data_local_rtc(Context *c) { - int r; _cleanup_free_ char *s = NULL, *w = NULL; + int r; assert(c); @@ -543,19 +537,16 @@ static int property_get_rtc_time( void *userdata, sd_bus_error *error) { - struct tm tm; - usec_t t; + struct tm tm = {}; + usec_t t = 0; int r; - zero(tm); r = clock_get_hwclock(&tm); - if (r == -EBUSY) { + if (r == -EBUSY) log_warning("/dev/rtc is busy. Is somebody keeping it open continuously? That's not a good idea... Returning a bogus RTC timestamp."); - t = 0; - } else if (r == -ENOENT) { + else if (r == -ENOENT) log_debug("/dev/rtc not found."); - t = 0; /* no RTC found */ - } else if (r < 0) + else if (r < 0) return sd_bus_error_set_errnof(error, r, "Failed to read RTC: %m"); else t = (usec_t) timegm(&tm) * USEC_PER_SEC; From ad7fb9434c8883cc81b58042613188a8e76214f0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Sun, 4 Aug 2019 11:06:59 +0200 Subject: [PATCH 2/3] timedated: log about unit enablement actions and enhance logs in general The general idea is that for things which can occur repeatedly, like SetNTP being called with the same argument, we only log at debug level. For things which change state, like when we realize that a unit that wasn't enabled before needs to be enabled, we log at info level. Also, don't return success if there are no units loaded. --- src/timedate/timedated.c | 64 ++++++++++++++++++++++++++++++++-------- 1 file changed, 52 insertions(+), 12 deletions(-) diff --git a/src/timedate/timedated.c b/src/timedate/timedated.c index 706e0ff448..70f720e2fe 100644 --- a/src/timedate/timedated.c +++ b/src/timedate/timedated.c @@ -61,6 +61,25 @@ typedef struct Context { LIST_HEAD(UnitStatusInfo, units); } Context; +#define log_unit_full(unit, level, error, ...) \ + ({ \ + const UnitStatusInfo *_u = (unit); \ + log_object_internal(level, error, PROJECT_FILE, __LINE__, __func__, \ + "UNIT=", _u->name, NULL, NULL, ##__VA_ARGS__); \ + }) + +#define log_unit_debug(unit, ...) log_unit_full(unit, LOG_DEBUG, 0, ##__VA_ARGS__) +#define log_unit_info(unit, ...) log_unit_full(unit, LOG_INFO, 0, ##__VA_ARGS__) +#define log_unit_notice(unit, ...) log_unit_full(unit, LOG_NOTICE, 0, ##__VA_ARGS__) +#define log_unit_warning(unit, ...) log_unit_full(unit, LOG_WARNING, 0, ##__VA_ARGS__) +#define log_unit_error(unit, ...) log_unit_full(unit, LOG_ERR, 0, ##__VA_ARGS__) + +#define log_unit_debug_errno(unit, error, ...) log_unit_full(unit, LOG_DEBUG, error, ##__VA_ARGS__) +#define log_unit_info_errno(unit, error, ...) log_unit_full(unit, LOG_INFO, error, ##__VA_ARGS__) +#define log_unit_notice_errno(unit, error, ...) log_unit_full(unit, LOG_NOTICE, error, ##__VA_ARGS__) +#define log_unit_warning_errno(unit, error, ...) log_unit_full(unit, LOG_WARNING, error, ##__VA_ARGS__) +#define log_unit_error_errno(unit, error, ...) log_unit_full(unit, LOG_ERR, error, ##__VA_ARGS__) + static void unit_status_info_clear(UnitStatusInfo *p) { assert(p); @@ -95,7 +114,7 @@ static void context_clear(Context *c) { } } -static int context_add_ntp_service(Context *c, const char *s) { +static int context_add_ntp_service(Context *c, const char *s, const char *source) { UnitStatusInfo *u; if (!unit_name_is_valid(s, UNIT_NAME_PLAIN)) @@ -117,6 +136,7 @@ static int context_add_ntp_service(Context *c, const char *s) { } LIST_APPEND(units, c->units, u); + log_unit_debug(u, "added from %s.", source); return 0; } @@ -131,7 +151,7 @@ static int context_parse_ntp_services_from_environment(Context *c) { if (!env) return 0; - log_debug("Using list of ntp services from environment variable $SYSTEMD_TIMEDATED_NTP_SERVICES."); + log_debug("Using list of ntp services from environment variable $SYSTEMD_TIMEDATED_NTP_SERVICES=%s.", env); for (p = env;;) { _cleanup_free_ char *word = NULL; @@ -146,7 +166,7 @@ static int context_parse_ntp_services_from_environment(Context *c) { break; } - r = context_add_ntp_service(c, word); + r = context_add_ntp_service(c, word, "$SYSTEMD_TIMEDATED_NTP_SERVICES"); if (r < 0) log_warning_errno(r, "Failed to add NTP service \"%s\", ignoring: %m", word); } @@ -190,7 +210,7 @@ static int context_parse_ntp_services_from_disk(Context *c) { if (isempty(word) || startswith("#", word)) continue; - r = context_add_ntp_service(c, word); + r = context_add_ntp_service(c, word, *f); if (r < 0) log_warning_errno(r, "Failed to add NTP service \"%s\", ignoring: %m", word); } @@ -400,7 +420,7 @@ static int context_update_ntp_status(Context *c, sd_bus *bus, sd_bus_message *m) NULL, u); if (r < 0) - return log_error_errno(r, "Failed to get properties: %s", bus_error_message(&error, r)); + return log_unit_error_errno(u, r, "Failed to get properties: %s", bus_error_message(&error, r)); } return 0; @@ -431,7 +451,9 @@ static int match_job_removed(sd_bus_message *m, void *userdata, sd_bus_error *er if (n == 0) { c->slot_job_removed = sd_bus_slot_unref(c->slot_job_removed); - (void) sd_bus_emit_properties_changed(sd_bus_message_get_bus(m), "/org/freedesktop/timedate1", "org.freedesktop.timedate1", "NTP", NULL); + (void) sd_bus_emit_properties_changed(sd_bus_message_get_bus(m), + "/org/freedesktop/timedate1", "org.freedesktop.timedate1", "NTP", + NULL); } return 0; @@ -457,6 +479,8 @@ static int unit_start_or_stop(UnitStatusInfo *u, sd_bus *bus, sd_bus_error *erro "ss", u->name, "replace"); + log_unit_full(u, r < 0 ? LOG_WARNING : LOG_DEBUG, r, + "%s unit: %m", start ? "Starting" : "Stopping"); if (r < 0) return r; @@ -480,8 +504,12 @@ static int unit_enable_or_disable(UnitStatusInfo *u, sd_bus *bus, sd_bus_error * /* Call context_update_ntp_status() to update UnitStatusInfo before calling this. */ - if (streq(u->unit_file_state, "enabled") == enable) + if (streq(u->unit_file_state, "enabled") == enable) { + log_unit_debug(u, "already %sd.", enable_disable(enable)); return 0; + } + + log_unit_info(u, "%s unit.", enable ? "Enabling" : "Disabling"); if (enable) r = sd_bus_call_method( @@ -683,7 +711,9 @@ static int method_set_timezone(sd_bus_message *m, void *userdata, sd_bus_error * "DAYLIGHT=%i", daylight, LOG_MESSAGE("Changed time zone to '%s' (%s).", c->zone, tzname[daylight])); - (void) sd_bus_emit_properties_changed(sd_bus_message_get_bus(m), "/org/freedesktop/timedate1", "org.freedesktop.timedate1", "Timezone", NULL); + (void) sd_bus_emit_properties_changed(sd_bus_message_get_bus(m), + "/org/freedesktop/timedate1", "org.freedesktop.timedate1", "Timezone", + NULL); return sd_bus_reply_method_return(m, NULL); } @@ -723,8 +753,8 @@ static int method_set_local_rtc(sd_bus_message *m, void *userdata, sd_bus_error /* 1. Write new configuration file */ r = context_write_data_local_rtc(c); if (r < 0) { - log_error_errno(r, "Failed to set RTC to local/UTC: %m"); - return sd_bus_error_set_errnof(error, r, "Failed to set RTC to local/UTC: %m"); + log_error_errno(r, "Failed to set RTC to %s: %m", lrtc ? "local" : "UTC"); + return sd_bus_error_set_errnof(error, r, "Failed to set RTC to %s: %m", lrtc ? "local" : "UTC"); } /* 2. Tell the kernel our timezone */ @@ -775,7 +805,9 @@ static int method_set_local_rtc(sd_bus_message *m, void *userdata, sd_bus_error log_info("RTC configured to %s time.", c->local_rtc ? "local" : "UTC"); - (void) sd_bus_emit_properties_changed(sd_bus_message_get_bus(m), "/org/freedesktop/timedate1", "org.freedesktop.timedate1", "LocalRTC", NULL); + (void) sd_bus_emit_properties_changed(sd_bus_message_get_bus(m), + "/org/freedesktop/timedate1", "org.freedesktop.timedate1", "LocalRTC", + NULL); return sd_bus_reply_method_return(m, NULL); } @@ -880,6 +912,7 @@ static int method_set_ntp(sd_bus_message *m, void *userdata, sd_bus_error *error sd_bus *bus = sd_bus_message_get_bus(m); Context *c = userdata; UnitStatusInfo *u; + const UnitStatusInfo *selected = NULL; int enable, interactive, q, r; assert(m); @@ -952,6 +985,7 @@ static int method_set_ntp(sd_bus_message *m, void *userdata, sd_bus_error *error continue; r = unit_start_or_stop(u, bus, error, enable); + selected = u; break; } @@ -962,16 +996,22 @@ static int method_set_ntp(sd_bus_message *m, void *userdata, sd_bus_error *error continue; r = unit_start_or_stop(u, bus, error, enable); + selected = u; break; } if (r < 0) return r; + if (enable && !selected) + return log_error_errno(SYNTHETIC_ERRNO(ENOENT), "No NTP service found to enable."); if (slot) c->slot_job_removed = TAKE_PTR(slot); - log_info("Set NTP to %sd", enable_disable(enable)); + if (selected) + log_info("Set NTP to enabled (%s).", selected->name); + else + log_info("Set NTP to disabled."); return sd_bus_reply_method_return(m, NULL); } From 0957790b5f8e1526877306c9727e6248d905bb9a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Mon, 5 Aug 2019 12:50:11 +0200 Subject: [PATCH 3/3] timedated: always enable&start the service with highest priority This removes a special case that was implemented before: if some service was already enabled, we'd treat it as having higher priority. From https://bugzilla.redhat.com/show_bug.cgi?id=1735584#c4: > Setting ntp off and on should give the same result as just setting it > on. There should be no stickiness (hidden state). It should behave like > running an ansible role. > > The other service might have been enabled because no other was installed at > the time. If I install a new NTP service with a higher priority, setting ntp > on should enable and start the new service, and disable all other. Also, if > for some reason multiple services are enabled, after setting ntp on there > should be only one enabled to avoid systemd selecting between them randomly > on the next boot. --- src/timedate/timedated.c | 61 ++++++++++++++-------------------------- 1 file changed, 21 insertions(+), 40 deletions(-) diff --git a/src/timedate/timedated.c b/src/timedate/timedated.c index 70f720e2fe..4f15a400ab 100644 --- a/src/timedate/timedated.c +++ b/src/timedate/timedated.c @@ -243,20 +243,6 @@ static int context_ntp_service_is_active(Context *c) { return count; } -static int context_ntp_service_is_enabled(Context *c) { - UnitStatusInfo *info; - int count = 0; - - assert(c); - - /* Call context_update_ntp_status() to update UnitStatusInfo before calling this. */ - - LIST_FOREACH(units, info, c->units) - count += !STRPTR_IN_SET(info->unit_file_state, "masked", "masked-runtime", "disabled", "bad"); - - return count; -} - static int context_ntp_service_exists(Context *c) { UnitStatusInfo *info; int count = 0; @@ -961,43 +947,38 @@ static int method_set_ntp(sd_bus_message *m, void *userdata, sd_bus_error *error return r; } - if (!enable) + if (enable) LIST_FOREACH(units, u, c->units) { + bool enable_this_one = !selected; + if (!streq(u->load_state, "loaded")) continue; - q = unit_enable_or_disable(u, bus, error, enable); - if (q < 0) - r = q; - - q = unit_start_or_stop(u, bus, error, enable); - if (q < 0) - r = q; - } - - else if (context_ntp_service_is_enabled(c) <= 0) - LIST_FOREACH(units, u, c->units) { - if (!streq(u->load_state, "loaded")) - continue; - - r = unit_enable_or_disable(u, bus, error, enable); + r = unit_enable_or_disable(u, bus, error, enable_this_one); if (r < 0) - continue; + /* If enablement failed, don't start this unit. */ + enable_this_one = false; - r = unit_start_or_stop(u, bus, error, enable); - selected = u; - break; + r = unit_start_or_stop(u, bus, error, enable_this_one); + if (r < 0) + log_unit_warning_errno(u, r, "Failed to %s %sd NTP unit, ignoring: %m", + enable_this_one ? "start" : "stop", + enable_disable(enable_this_one)); + if (enable_this_one) + selected = u; } - else LIST_FOREACH(units, u, c->units) { - if (!streq(u->load_state, "loaded") || - !streq(u->unit_file_state, "enabled")) + if (!streq(u->load_state, "loaded")) continue; - r = unit_start_or_stop(u, bus, error, enable); - selected = u; - break; + q = unit_enable_or_disable(u, bus, error, false); + if (q < 0) + r = q; + + q = unit_start_or_stop(u, bus, error, false); + if (q < 0) + r = q; } if (r < 0)