From 230f663e3e85d2860de29cb59c44671b72006cf8 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Fri, 7 Apr 2023 04:07:17 +0900 Subject: [PATCH 1/9] update-utmp: use verbs No functional change, just refactoring. --- src/update-utmp/update-utmp.c | 39 +++++++++++++++-------------------- 1 file changed, 17 insertions(+), 22 deletions(-) diff --git a/src/update-utmp/update-utmp.c b/src/update-utmp/update-utmp.c index 4996272eb3..e2faace3f7 100644 --- a/src/update-utmp/update-utmp.c +++ b/src/update-utmp/update-utmp.c @@ -25,6 +25,7 @@ #include "strv.h" #include "unit-name.h" #include "utmp-wtmp.h" +#include "verbs.h" typedef struct Context { sd_bus *bus; @@ -105,12 +106,10 @@ static int get_current_runlevel(Context *c) { return 0; } -static int on_reboot(Context *c) { +static int on_reboot(int argc, char *argv[], void *userdata) { + Context *c = ASSERT_PTR(userdata); + usec_t t, boottime; int r = 0, q; - usec_t t; - usec_t boottime; - - assert(c); /* We finished start-up, so let's write the utmp * record and send the audit msg */ @@ -139,15 +138,15 @@ static int on_reboot(Context *c) { return r; } -static int on_shutdown(Context *c) { +static int on_shutdown(int argc, char *argv[], void *userdata) { int r = 0, q; - assert(c); - /* We started shut-down, so let's write the utmp * record and send the audit msg */ #if HAVE_AUDIT + Context *c = ASSERT_PTR(userdata); + if (c->audit_fd >= 0) if (audit_log_user_comm_message(c->audit_fd, AUDIT_SYSTEM_SHUTDOWN, "", "systemd-update-utmp", NULL, NULL, NULL, 1) < 0 && errno != EPERM) @@ -161,11 +160,10 @@ static int on_shutdown(Context *c) { return r; } -static int on_runlevel(Context *c) { +static int on_runlevel(int argc, char *argv[], void *userdata) { + Context *c = ASSERT_PTR(userdata); int r = 0, q, previous, runlevel; - assert(c); - /* We finished changing runlevel, so let's write the * utmp record and send the audit msg */ @@ -213,6 +211,13 @@ static int on_runlevel(Context *c) { } static int run(int argc, char *argv[]) { + static const Verb verbs[] = { + { "reboot", 1, 1, 0, on_reboot }, + { "shutdown", 1, 1, 0, on_shutdown }, + { "runlevel", 1, 1, 0, on_runlevel }, + {} + }; + _cleanup_(context_clear) Context c = { #if HAVE_AUDIT .audit_fd = -EBADF, @@ -220,10 +225,6 @@ static int run(int argc, char *argv[]) { }; int r; - if (argc != 2) - return log_error_errno(SYNTHETIC_ERRNO(EINVAL), - "This program requires one argument."); - log_setup(); umask(0022); @@ -239,13 +240,7 @@ static int run(int argc, char *argv[]) { if (r < 0) return log_error_errno(r, "Failed to get D-Bus connection: %m"); - if (streq(argv[1], "reboot")) - return on_reboot(&c); - if (streq(argv[1], "shutdown")) - return on_shutdown(&c); - if (streq(argv[1], "runlevel")) - return on_runlevel(&c); - return log_error_errno(SYNTHETIC_ERRNO(EINVAL), "Unknown command %s", argv[1]); + return dispatch_verb(argc, argv, verbs, &c); } DEFINE_MAIN_FUNCTION(run); From 309491e4cf510c9fabf75b48f6ffd196bee2a8ee Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Fri, 7 Apr 2023 04:13:57 +0900 Subject: [PATCH 2/9] update-utmp: rebreak comments --- src/update-utmp/update-utmp.c | 29 +++++++++++------------------ 1 file changed, 11 insertions(+), 18 deletions(-) diff --git a/src/update-utmp/update-utmp.c b/src/update-utmp/update-utmp.c index e2faace3f7..8f2fa17e6b 100644 --- a/src/update-utmp/update-utmp.c +++ b/src/update-utmp/update-utmp.c @@ -66,11 +66,9 @@ static int get_current_runlevel(Context *c) { const int runlevel; const char *special; } table[] = { - /* The first target of this list that is active or has - * a job scheduled wins. We prefer runlevels 5 and 3 - * here over the others, since these are the main - * runlevels used on Fedora. It might make sense to - * change the order on some distributions. */ + /* The first target of this list that is active or has a job scheduled wins. We prefer + * runlevels 5 and 3 here over the others, since these are the main runlevels used on Fedora. + * It might make sense to change the order on some distributions. */ { '5', SPECIAL_GRAPHICAL_TARGET }, { '3', SPECIAL_MULTI_USER_TARGET }, { '1', SPECIAL_RESCUE_TARGET }, @@ -111,8 +109,7 @@ static int on_reboot(int argc, char *argv[], void *userdata) { usec_t t, boottime; int r = 0, q; - /* We finished start-up, so let's write the utmp - * record and send the audit msg */ + /* We finished start-up, so let's write the utmp record and send the audit msg. */ #if HAVE_AUDIT if (c->audit_fd >= 0) @@ -121,15 +118,13 @@ static int on_reboot(int argc, char *argv[], void *userdata) { r = log_error_errno(errno, "Failed to send audit message: %m"); #endif - /* If this call fails it will return 0, which - * utmp_put_reboot() will then fix to the current time */ + /* If this call fails it will return 0, which utmp_put_reboot() will then fix to the current time. */ t = get_startup_monotonic_time(c); boottime = map_clock_usec(t, CLOCK_MONOTONIC, CLOCK_REALTIME); - /* We query the recorded monotonic time here (instead of the system clock CLOCK_REALTIME), - * even though we actually want the system clock time. That's because there's a likely - * chance that the system clock wasn't set right during early boot. By manually converting - * the monotonic clock to the system clock here we can compensate - * for incorrectly set clocks during early boot. */ + /* We query the recorded monotonic time here (instead of the system clock CLOCK_REALTIME), even + * though we actually want the system clock time. That's because there's a likely chance that the + * system clock wasn't set right during early boot. By manually converting the monotonic clock to the + * system clock here we can compensate for incorrectly set clocks during early boot. */ q = utmp_put_reboot(boottime); if (q < 0) @@ -141,8 +136,7 @@ static int on_reboot(int argc, char *argv[], void *userdata) { static int on_shutdown(int argc, char *argv[], void *userdata) { int r = 0, q; - /* We started shut-down, so let's write the utmp - * record and send the audit msg */ + /* We started shut-down, so let's write the utmp record and send the audit msg. */ #if HAVE_AUDIT Context *c = ASSERT_PTR(userdata); @@ -164,8 +158,7 @@ static int on_runlevel(int argc, char *argv[], void *userdata) { Context *c = ASSERT_PTR(userdata); int r = 0, q, previous, runlevel; - /* We finished changing runlevel, so let's write the - * utmp record and send the audit msg */ + /* We finished changing runlevel, so let's write the utmp record and send the audit msg. */ /* First, get last runlevel */ q = utmp_get_runlevel(&previous, NULL); From 3950d8f693216ce755ddd2e4078018015d108ac4 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Fri, 7 Apr 2023 04:26:19 +0900 Subject: [PATCH 3/9] update-utmp: modernize get_startup_monotonic_time() This also downgrade error level, as the failure will be ignored. No functional change, just refactoring. --- src/update-utmp/update-utmp.c | 25 ++++++++++++++----------- 1 file changed, 14 insertions(+), 11 deletions(-) diff --git a/src/update-utmp/update-utmp.c b/src/update-utmp/update-utmp.c index 8f2fa17e6b..7121f304c7 100644 --- a/src/update-utmp/update-utmp.c +++ b/src/update-utmp/update-utmp.c @@ -45,20 +45,23 @@ static void context_clear(Context *c) { #endif } -static usec_t get_startup_monotonic_time(Context *c) { +static int get_startup_monotonic_time(Context *c, usec_t *ret) { _cleanup_(sd_bus_error_free) sd_bus_error error = SD_BUS_ERROR_NULL; - usec_t t = 0; int r; assert(c); + assert(ret); - r = bus_get_property_trivial(c->bus, bus_systemd_mgr, "UserspaceTimestampMonotonic", &error, 't', &t); - if (r < 0) { - log_error_errno(r, "Failed to get timestamp: %s", bus_error_message(&error, r)); - return 0; - } + r = bus_get_property_trivial( + c->bus, + bus_systemd_mgr, + "UserspaceTimestampMonotonic", + &error, + 't', ret); + if (r < 0) + return log_warning_errno(r, "Failed to get timestamp, ignoring: %s", bus_error_message(&error, r)); - return t; + return 0; } static int get_current_runlevel(Context *c) { @@ -106,7 +109,7 @@ static int get_current_runlevel(Context *c) { static int on_reboot(int argc, char *argv[], void *userdata) { Context *c = ASSERT_PTR(userdata); - usec_t t, boottime; + usec_t t = 0, boottime; int r = 0, q; /* We finished start-up, so let's write the utmp record and send the audit msg. */ @@ -118,8 +121,8 @@ static int on_reboot(int argc, char *argv[], void *userdata) { r = log_error_errno(errno, "Failed to send audit message: %m"); #endif - /* If this call fails it will return 0, which utmp_put_reboot() will then fix to the current time. */ - t = get_startup_monotonic_time(c); + /* If this call fails, then utmp_put_reboot() will fix to the current time. */ + (void) get_startup_monotonic_time(c, &t); boottime = map_clock_usec(t, CLOCK_MONOTONIC, CLOCK_REALTIME); /* We query the recorded monotonic time here (instead of the system clock CLOCK_REALTIME), even * though we actually want the system clock time. That's because there's a likely chance that the From 4c40ab203c9c9e485aac1ae74d407b8ece633471 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Fri, 7 Apr 2023 04:31:21 +0900 Subject: [PATCH 4/9] update-utmp: swap q <-> r We usually use 'r' for general purpose. No functional change, just refactoring. --- src/update-utmp/update-utmp.c | 44 +++++++++++++++++------------------ 1 file changed, 22 insertions(+), 22 deletions(-) diff --git a/src/update-utmp/update-utmp.c b/src/update-utmp/update-utmp.c index 7121f304c7..e6739db1c3 100644 --- a/src/update-utmp/update-utmp.c +++ b/src/update-utmp/update-utmp.c @@ -110,7 +110,7 @@ static int get_current_runlevel(Context *c) { static int on_reboot(int argc, char *argv[], void *userdata) { Context *c = ASSERT_PTR(userdata); usec_t t = 0, boottime; - int r = 0, q; + int r, q = 0; /* We finished start-up, so let's write the utmp record and send the audit msg. */ @@ -118,7 +118,7 @@ static int on_reboot(int argc, char *argv[], void *userdata) { if (c->audit_fd >= 0) if (audit_log_user_comm_message(c->audit_fd, AUDIT_SYSTEM_BOOT, "", "systemd-update-utmp", NULL, NULL, NULL, 1) < 0 && errno != EPERM) - r = log_error_errno(errno, "Failed to send audit message: %m"); + q = log_error_errno(errno, "Failed to send audit message: %m"); #endif /* If this call fails, then utmp_put_reboot() will fix to the current time. */ @@ -129,15 +129,15 @@ static int on_reboot(int argc, char *argv[], void *userdata) { * system clock wasn't set right during early boot. By manually converting the monotonic clock to the * system clock here we can compensate for incorrectly set clocks during early boot. */ - q = utmp_put_reboot(boottime); - if (q < 0) - r = log_error_errno(q, "Failed to write utmp record: %m"); + r = utmp_put_reboot(boottime); + if (r < 0) + return log_error_errno(r, "Failed to write utmp record: %m"); - return r; + return q; } static int on_shutdown(int argc, char *argv[], void *userdata) { - int r = 0, q; + int r, q = 0; /* We started shut-down, so let's write the utmp record and send the audit msg. */ @@ -147,28 +147,28 @@ static int on_shutdown(int argc, char *argv[], void *userdata) { if (c->audit_fd >= 0) if (audit_log_user_comm_message(c->audit_fd, AUDIT_SYSTEM_SHUTDOWN, "", "systemd-update-utmp", NULL, NULL, NULL, 1) < 0 && errno != EPERM) - r = log_error_errno(errno, "Failed to send audit message: %m"); + q = log_error_errno(errno, "Failed to send audit message: %m"); #endif - q = utmp_put_shutdown(); - if (q < 0) - r = log_error_errno(q, "Failed to write utmp record: %m"); + r = utmp_put_shutdown(); + if (r < 0) + return log_error_errno(r, "Failed to write utmp record: %m"); - return r; + return q; } static int on_runlevel(int argc, char *argv[], void *userdata) { Context *c = ASSERT_PTR(userdata); - int r = 0, q, previous, runlevel; + int r, q = 0, previous, runlevel; /* We finished changing runlevel, so let's write the utmp record and send the audit msg. */ /* First, get last runlevel */ - q = utmp_get_runlevel(&previous, NULL); + r = utmp_get_runlevel(&previous, NULL); - if (q < 0) { - if (!IN_SET(q, -ESRCH, -ENOENT)) - return log_error_errno(q, "Failed to get current runlevel: %m"); + if (r < 0) { + if (!IN_SET(r, -ESRCH, -ENOENT)) + return log_error_errno(r, "Failed to get current runlevel: %m"); previous = 0; } @@ -195,15 +195,15 @@ static int on_runlevel(int argc, char *argv[], void *userdata) { if (audit_log_user_comm_message(c->audit_fd, AUDIT_SYSTEM_RUNLEVEL, s, "systemd-update-utmp", NULL, NULL, NULL, 1) < 0 && errno != EPERM) - r = log_error_errno(errno, "Failed to send audit message: %m"); + q = log_error_errno(errno, "Failed to send audit message: %m"); } #endif - q = utmp_put_runlevel(runlevel, previous); - if (q < 0 && !IN_SET(q, -ESRCH, -ENOENT)) - return log_error_errno(q, "Failed to write utmp record: %m"); + r = utmp_put_runlevel(runlevel, previous); + if (r < 0 && !IN_SET(r, -ESRCH, -ENOENT)) + return log_error_errno(r, "Failed to write utmp record: %m"); - return r; + return q; } static int run(int argc, char *argv[]) { From 86da32ee0c081d5d740ed5ff2d1d58c0d697c324 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Fri, 7 Apr 2023 04:34:54 +0900 Subject: [PATCH 5/9] update-utmp: downgrade log level of ignored failure --- src/update-utmp/update-utmp.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/update-utmp/update-utmp.c b/src/update-utmp/update-utmp.c index e6739db1c3..5656ca2761 100644 --- a/src/update-utmp/update-utmp.c +++ b/src/update-utmp/update-utmp.c @@ -229,8 +229,8 @@ static int run(int argc, char *argv[]) { /* If the kernel lacks netlink or audit support, don't worry about it. */ c.audit_fd = audit_open(); if (c.audit_fd < 0) - log_full_errno(IN_SET(errno, EAFNOSUPPORT, EPROTONOSUPPORT) ? LOG_DEBUG : LOG_ERR, - errno, "Failed to connect to audit log: %m"); + log_full_errno(IN_SET(errno, EAFNOSUPPORT, EPROTONOSUPPORT) ? LOG_DEBUG : LOG_WARNING, + errno, "Failed to connect to audit log, ignoring: %m"); #endif r = bus_connect_system_systemd(&c.bus); if (r < 0) From 87ae54533c6ad7047a152b7238f682eda334a9e0 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Fri, 7 Apr 2023 18:44:22 +0900 Subject: [PATCH 6/9] update-utmp: update log message --- src/update-utmp/update-utmp.c | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/update-utmp/update-utmp.c b/src/update-utmp/update-utmp.c index 5656ca2761..2f6d582da9 100644 --- a/src/update-utmp/update-utmp.c +++ b/src/update-utmp/update-utmp.c @@ -165,10 +165,9 @@ static int on_runlevel(int argc, char *argv[], void *userdata) { /* First, get last runlevel */ r = utmp_get_runlevel(&previous, NULL); - if (r < 0) { if (!IN_SET(r, -ESRCH, -ENOENT)) - return log_error_errno(r, "Failed to get current runlevel: %m"); + return log_error_errno(r, "Failed to get the last runlevel from utmp: %m"); previous = 0; } @@ -178,7 +177,7 @@ static int on_runlevel(int argc, char *argv[], void *userdata) { if (runlevel < 0) return runlevel; if (runlevel == 0) { - log_warning("Failed to get new runlevel, utmp update skipped."); + log_warning("Failed to get the current runlevel, utmp update skipped."); return 0; } From fcb2343175d80b45659817e02a7d0d4771d0a854 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Fri, 7 Apr 2023 04:49:07 +0900 Subject: [PATCH 7/9] update-utmp: reconnect after sleep when PID1 is reexecuting Fixes #27167. --- src/update-utmp/update-utmp.c | 67 ++++++++++++++++++++++++----------- 1 file changed, 46 insertions(+), 21 deletions(-) diff --git a/src/update-utmp/update-utmp.c b/src/update-utmp/update-utmp.c index 2f6d582da9..5651ec11da 100644 --- a/src/update-utmp/update-utmp.c +++ b/src/update-utmp/update-utmp.c @@ -20,6 +20,7 @@ #include "macro.h" #include "main-func.h" #include "process-util.h" +#include "random-util.h" #include "special.h" #include "stdio-util.h" #include "strv.h" @@ -76,35 +77,59 @@ static int get_current_runlevel(Context *c) { { '3', SPECIAL_MULTI_USER_TARGET }, { '1', SPECIAL_RESCUE_TARGET }, }; - - _cleanup_(sd_bus_error_free) sd_bus_error error = SD_BUS_ERROR_NULL; int r; assert(c); - for (size_t i = 0; i < ELEMENTSOF(table); i++) { - _cleanup_free_ char *state = NULL, *path = NULL; + for (unsigned n_attempts = 0;;) { + FOREACH_ARRAY(e, table, ELEMENTSOF(table)) { + _cleanup_(sd_bus_error_free) sd_bus_error error = SD_BUS_ERROR_NULL; + _cleanup_free_ char *state = NULL, *path = NULL; - path = unit_dbus_path_from_name(table[i].special); - if (!path) - return log_oom(); + path = unit_dbus_path_from_name(e->special); + if (!path) + return log_oom(); - r = sd_bus_get_property_string( - c->bus, - "org.freedesktop.systemd1", - path, - "org.freedesktop.systemd1.Unit", - "ActiveState", - &error, - &state); + r = sd_bus_get_property_string( + c->bus, + "org.freedesktop.systemd1", + path, + "org.freedesktop.systemd1.Unit", + "ActiveState", + &error, + &state); + if ((r == -ENOTCONN || + sd_bus_error_has_names(&error, + SD_BUS_ERROR_NO_REPLY, + SD_BUS_ERROR_DISCONNECTED)) && + ++n_attempts < 64) { + + /* systemd might have dropped off momentarily, let's not make this an error, + * and wait some random time. Let's pick a random time in the range 0ms…250ms, + * linearly scaled by the number of failed attempts. */ + + usec_t usec = random_u64_range(UINT64_C(10) * USEC_PER_MSEC + + UINT64_C(240) * USEC_PER_MSEC * n_attempts/64); + log_debug_errno(r, "Failed to get state of %s, retrying after %s: %s", + e->special, FORMAT_TIMESPAN(usec, USEC_PER_MSEC), bus_error_message(&error, r)); + (void) usleep(usec); + goto reconnect; + } + if (r < 0) + return log_warning_errno(r, "Failed to get state of %s: %s", e->special, bus_error_message(&error, r)); + + if (STR_IN_SET(state, "active", "reloading")) + return e->runlevel; + } + + return 0; + +reconnect: + c->bus = sd_bus_flush_close_unref(c->bus); + r = bus_connect_system_systemd(&c->bus); if (r < 0) - return log_warning_errno(r, "Failed to get state: %s", bus_error_message(&error, r)); - - if (STR_IN_SET(state, "active", "reloading")) - return table[i].runlevel; + return log_error_errno(r, "Failed to reconnect to system bus: %m"); } - - return 0; } static int on_reboot(int argc, char *argv[], void *userdata) { From 08bc702b12e5e17c2a167963616bf36c8f214ef0 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Fri, 7 Apr 2023 10:05:40 +0900 Subject: [PATCH 8/9] test: drop a workaround Follow-up for 61961e693d3ba71386068947d85078c086e455e4. --- test/units/testsuite-01.service | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/test/units/testsuite-01.service b/test/units/testsuite-01.service index a55cc526a5..9074e0968f 100644 --- a/test/units/testsuite-01.service +++ b/test/units/testsuite-01.service @@ -1,10 +1,7 @@ # SPDX-License-Identifier: LGPL-2.1-or-later [Unit] Description=TEST-01-BASIC -# Order the test unit after systemd-update-utmp-runlevel.service, since -# the service doesn't play well with daemon-reexec -# See: https://github.com/systemd/systemd/issues/27167 -After=multi-user.target systemd-update-utmp-runlevel.service +After=multi-user.target Wants=systemd-resolved.service systemd-networkd.service [Service] From d689f70a2c18666bbf6500df7a53962a8f3e91a4 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Wed, 26 Apr 2023 23:56:50 +0900 Subject: [PATCH 9/9] test: add test case for systemd-update-utmp vs daemon-reexec --- test/units/testsuite-01.sh | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/test/units/testsuite-01.sh b/test/units/testsuite-01.sh index 91dd47ca14..475eaa2923 100755 --- a/test/units/testsuite-01.sh +++ b/test/units/testsuite-01.sh @@ -44,4 +44,17 @@ systemctl daemon-reload # of systemd-analyze blame. See issue #27187. systemd-analyze blame +# Test for 'systemd-update-utmp runlevel' vs 'systemctl daemon-reexec'. +# See issue #27163. +# shellcheck disable=SC2034 +for _ in {0..10}; do + systemctl daemon-reexec & + pid_reexec=$! + # shellcheck disable=SC2034 + for _ in {0..10}; do + SYSTEMD_LOG_LEVEL=debug /usr/lib/systemd/systemd-update-utmp runlevel + done + wait "$pid_reexec" +done + echo OK >/testok