From 58441bc177bb1bcdeceff74d3ae6b6d9f93a7fbe Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Wed, 30 Jun 2021 17:02:45 +0200 Subject: [PATCH 1/3] core: emit nicer log message for exiting ConditionExec processes See https://bugzilla.redhat.com/show_bug.cgi?id=1973058: we would log something like: systemd[244]: Starting willskip.service... systemd[244]: willskip.service: Control process exited, code=exited, status=2/INVALIDARGUMENT systemd[244]: willskip.service: Skipped due to 'exec-condition'. systemd[244]: Condition check resulted in willskip.service being skipped. The line with 'Control process exited' would be at LOG_NOTICE level. With the patch: systemd[244]: Starting willskip.service... systemd[244]: willskip.service: Skipped due to 'exec-condition'. systemd[244]: Condition check resulted in willskip.service being skipped. Debug logs: systemd[244]: Starting willskip.service... systemd[244]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/willskip_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=8 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a systemd[244]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/willskip_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=9 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a systemd[244]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/job/46 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=10 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a systemd[11020]: Skipping PR_SET_MM, as we don't have privileges. systemd[11020]: willskip.service: Executing: sh -c 'exit 2' systemd[244]: Received SIGCHLD from PID 11020 (sh). systemd[244]: Child 11020 (sh) died (code=exited, status=2/INVALIDARGUMENT) systemd[244]: willskip.service: Child 11020 belongs to willskip.service. systemd[244]: willskip.service: Condition check process exited, code=exited, status=2/INVALIDARGUMENT (success) systemd[244]: willskip.service: Got final SIGCHLD for state condition. systemd[244]: willskip.service: Skipped due to 'exec-condition'. systemd[244]: willskip.service: Service will not restart (restart setting) systemd[244]: willskip.service: Changed condition -> dead systemd[244]: willskip.service: Job 46 willskip.service/start finished, result=done systemd[244]: Condition check resulted in willskip.service being skipped. --- src/core/service.c | 18 +++++++++++++++--- src/core/unit.c | 5 +++-- 2 files changed, 18 insertions(+), 5 deletions(-) diff --git a/src/core/service.c b/src/core/service.c index af5a2decf1..11b22c9446 100644 --- a/src/core/service.c +++ b/src/core/service.c @@ -3538,6 +3538,9 @@ static void service_sigchld_event(Unit *u, pid_t pid, int code, int status) { } } else if (s->control_pid == pid) { + const char *kind; + bool success; + s->control_pid = 0; if (s->control_command) { @@ -3552,15 +3555,24 @@ static void service_sigchld_event(Unit *u, pid_t pid, int code, int status) { if (f == SERVICE_FAILURE_EXIT_CODE && status < 255) { UNIT(s)->condition_result = false; f = SERVICE_SKIP_CONDITION; - } else if (f == SERVICE_SUCCESS) + success = true; + } else if (f == SERVICE_SUCCESS) { UNIT(s)->condition_result = true; + success = true; + } else + success = false; + + kind = "Condition check process"; + } else { + kind = "Control process"; + success = f == SERVICE_SUCCESS; } unit_log_process_exit( u, - "Control process", + kind, service_exec_command_to_string(s->control_command_id), - f == SERVICE_SUCCESS, + success, code, status); if (s->state != SERVICE_RELOAD && s->result == SERVICE_SUCCESS) diff --git a/src/core/unit.c b/src/core/unit.c index 3792cee711..be8e0ddef2 100644 --- a/src/core/unit.c +++ b/src/core/unit.c @@ -5576,12 +5576,13 @@ void unit_log_process_exit( log_unit_struct(u, level, "MESSAGE_ID=" SD_MESSAGE_UNIT_PROCESS_EXIT_STR, - LOG_UNIT_MESSAGE(u, "%s exited, code=%s, status=%i/%s", + LOG_UNIT_MESSAGE(u, "%s exited, code=%s, status=%i/%s%s", kind, sigchld_code_to_string(code), status, strna(code == CLD_EXITED ? exit_status_to_string(status, EXIT_STATUS_FULL) - : signal_to_string(status))), + : signal_to_string(status)), + success ? " (success)" : ""), "EXIT_CODE=%s", sigchld_code_to_string(code), "EXIT_STATUS=%i", status, "COMMAND=%s", strna(command), From e8616626eb0e48831d190e9ac2b0c4a72382ac30 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Wed, 30 Jun 2021 17:10:43 +0200 Subject: [PATCH 2/3] core/cgroup: inline more iterator variable declarations --- src/core/cgroup.c | 18 +++++++----------- 1 file changed, 7 insertions(+), 11 deletions(-) diff --git a/src/core/cgroup.c b/src/core/cgroup.c index 3cec8a5786..21b2055ca5 100644 --- a/src/core/cgroup.c +++ b/src/core/cgroup.c @@ -517,9 +517,8 @@ void cgroup_context_dump(Unit *u, FILE* f, const char *prefix) { LIST_FOREACH(device_limits, il, c->io_device_limits) { char buf[FORMAT_BYTES_MAX]; - CGroupIOLimitType type; - for (type = 0; type < _CGROUP_IO_LIMIT_TYPE_MAX; type++) + for (CGroupIOLimitType type = 0; type < _CGROUP_IO_LIMIT_TYPE_MAX; type++) if (il->limits[type] != cgroup_io_limit_defaults[type]) fprintf(f, "%s%s: %s %s\n", @@ -1347,9 +1346,8 @@ static void cgroup_context_apply( LIST_FOREACH(device_bandwidths, b, c->blockio_device_bandwidths) { uint64_t limits[_CGROUP_IO_LIMIT_TYPE_MAX]; - CGroupIOLimitType type; - for (type = 0; type < _CGROUP_IO_LIMIT_TYPE_MAX; type++) + for (CGroupIOLimitType type = 0; type < _CGROUP_IO_LIMIT_TYPE_MAX; type++) limits[type] = cgroup_io_limit_defaults[type]; limits[CGROUP_IO_RBPS_MAX] = b->rbps; @@ -1534,7 +1532,6 @@ static void cgroup_context_apply( static bool unit_get_needs_bpf_firewall(Unit *u) { CGroupContext *c; - Unit *p; assert(u); c = unit_get_cgroup_context(u); @@ -1549,7 +1546,7 @@ static bool unit_get_needs_bpf_firewall(Unit *u) { return true; /* If any parent slice has an IP access list defined, it applies too */ - for (p = UNIT_GET_SLICE(u); p; p = UNIT_GET_SLICE(p)) { + for (Unit *p = UNIT_GET_SLICE(u); p; p = UNIT_GET_SLICE(p)) { c = unit_get_cgroup_context(p); if (!c) return false; @@ -2163,7 +2160,6 @@ int unit_attach_pids_to_cgroup(Unit *u, Set *pids, const char *suffix_path) { r = 0; SET_FOREACH(pidp, pids) { pid_t pid = PTR_TO_PID(pidp); - CGroupController c; /* First, attach the PID to the main cgroup hierarchy */ q = cg_attach(SYSTEMD_CGROUP_CONTROLLER, p, pid); @@ -2200,7 +2196,7 @@ int unit_attach_pids_to_cgroup(Unit *u, Set *pids, const char *suffix_path) { /* In the legacy hierarchy, attach the process to the request cgroup if possible, and if not to the * innermost realized one */ - for (c = 0; c < _CGROUP_CONTROLLER_MAX; c++) { + for (CGroupController c = 0; c < _CGROUP_CONTROLLER_MAX; c++) { CGroupMask bit = CGROUP_CONTROLLER_TO_MASK(c); const char *realized; @@ -3137,7 +3133,6 @@ static int cg_bpf_mask_supported(CGroupMask *ret) { int manager_setup_cgroup(Manager *m) { _cleanup_free_ char *path = NULL; const char *scope_path; - CGroupController c; int r, all_unified; CGroupMask mask; char *e; @@ -3285,8 +3280,9 @@ int manager_setup_cgroup(Manager *m) { m->cgroup_supported |= mask; /* 10. Log which controllers are supported */ - for (c = 0; c < _CGROUP_CONTROLLER_MAX; c++) - log_debug("Controller '%s' supported: %s", cgroup_controller_to_string(c), yes_no(m->cgroup_supported & CGROUP_CONTROLLER_TO_MASK(c))); + for (CGroupController c = 0; c < _CGROUP_CONTROLLER_MAX; c++) + log_debug("Controller '%s' supported: %s", cgroup_controller_to_string(c), + yes_no(m->cgroup_supported & CGROUP_CONTROLLER_TO_MASK(c))); return 0; } From 7a2ba4078731a00fa105c38c283b2ce7789bb512 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Wed, 30 Jun 2021 17:17:41 +0200 Subject: [PATCH 3/3] core/cgroup: upgrade log level when we fail to rescope a pid See https://bugzilla.redhat.com/show_bug.cgi?id=1973058 again: systemd[1779]: Started Application launched by gnome-session-binary. systemd[1779]: app-glib-liveinst\x2dsetup-1897.scope: Failed to add PIDs to scope's control group: No such process systemd[1779]: app-glib-liveinst\x2dsetup-1897.scope: Failed with result 'resources'. systemd[1779]: Failed to start Application launched by gnome-session-binary. systemd[1779]: app-glib-xdg\x2duser\x2ddirs-1900.scope: Failed to add PIDs to scope's control group: No such process systemd[1779]: app-glib-xdg\x2duser\x2ddirs-1900.scope: Failed with result 'resources'. systemd[1779]: Failed to start Application launched by gnome-session-binary. systemd[1779]: app-gnome-gsettings\x2ddata\x2dconvert-1902.scope: Failed to add PIDs to scope's control group: No such process systemd[1779]: app-gnome-gsettings\x2ddata\x2dconvert-1902.scope: Failed with result 'resources'. systemd[1779]: Failed to start Application launched by gnome-session-binary. Since we don't show the PID anywhere, it can be quite hard to figure out what is going on. There may be logs from the pid above or below in the log, but we have no PID number to identify them. So let's upgrade the log from unit_attach_pids_to_cgroup() to tell us precisely which PIDs and why couldn't be handled. --- src/core/cgroup.c | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/src/core/cgroup.c b/src/core/cgroup.c index 21b2055ca5..2fcfb27093 100644 --- a/src/core/cgroup.c +++ b/src/core/cgroup.c @@ -2164,19 +2164,23 @@ int unit_attach_pids_to_cgroup(Unit *u, Set *pids, const char *suffix_path) { /* First, attach the PID to the main cgroup hierarchy */ q = cg_attach(SYSTEMD_CGROUP_CONTROLLER, p, pid); if (q < 0) { - log_unit_debug_errno(u, q, "Couldn't move process " PID_FMT " to requested cgroup '%s': %m", pid, p); + bool again = MANAGER_IS_USER(u->manager) && ERRNO_IS_PRIVILEGE(q); - if (MANAGER_IS_USER(u->manager) && ERRNO_IS_PRIVILEGE(q)) { + log_unit_full_errno(u, again ? LOG_DEBUG : LOG_INFO, q, + "Couldn't move process "PID_FMT" to%s requested cgroup '%s': %m", + pid, again ? " directly" : "", p); + + if (again) { int z; - /* If we are in a user instance, and we can't move the process ourselves due to - * permission problems, let's ask the system instance about it instead. Since it's more - * privileged it might be able to move the process across the leaves of a subtree who's - * top node is not owned by us. */ + /* If we are in a user instance, and we can't move the process ourselves due + * to permission problems, let's ask the system instance about it instead. + * Since it's more privileged it might be able to move the process across the + * leaves of a subtree whose top node is not owned by us. */ z = unit_attach_pid_to_cgroup_via_bus(u, pid, suffix_path); if (z < 0) - log_unit_debug_errno(u, z, "Couldn't move process " PID_FMT " to requested cgroup '%s' via the system bus either: %m", pid, p); + log_unit_info_errno(u, z, "Couldn't move process "PID_FMT" to requested cgroup '%s' (directly or via the system bus): %m", pid, p); else continue; /* When the bus thing worked via the bus we are fully done for this PID. */ }