From 8002fb97473cfd2758d8a37213cfb99baadc4e55 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 26 Sep 2017 17:42:57 +0200 Subject: [PATCH 1/9] execute: rework logging in setup_keyring() to include unit info Let's use log_unit_error() instead of log_error() everywhere (and friends). --- src/core/execute.c | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/src/core/execute.c b/src/core/execute.c index 0b49be2000..2baf824974 100644 --- a/src/core/execute.c +++ b/src/core/execute.c @@ -2192,13 +2192,13 @@ static int setup_keyring( keyring = keyctl(KEYCTL_JOIN_SESSION_KEYRING, 0, 0, 0, 0); if (keyring == -1) { if (errno == ENOSYS) - log_debug_errno(errno, "Kernel keyring not supported, ignoring."); + log_unit_debug_errno(u, errno, "Kernel keyring not supported, ignoring."); else if (IN_SET(errno, EACCES, EPERM)) - log_debug_errno(errno, "Kernel keyring access prohibited, ignoring."); + log_unit_debug_errno(u, errno, "Kernel keyring access prohibited, ignoring."); else if (errno == EDQUOT) - log_debug_errno(errno, "Out of kernel keyrings to allocate, ignoring."); + log_unit_debug_errno(u, errno, "Out of kernel keyrings to allocate, ignoring."); else - return log_error_errno(errno, "Setting up kernel keyring failed: %m"); + return log_unit_error_errno(u, errno, "Setting up kernel keyring failed: %m"); return 0; } @@ -2209,19 +2209,19 @@ static int setup_keyring( key = add_key("user", "invocation_id", &u->invocation_id, sizeof(u->invocation_id), KEY_SPEC_SESSION_KEYRING); if (key == -1) - log_debug_errno(errno, "Failed to add invocation ID to keyring, ignoring: %m"); + log_unit_debug_errno(u, errno, "Failed to add invocation ID to keyring, ignoring: %m"); else { if (keyctl(KEYCTL_SETPERM, key, KEY_POS_VIEW|KEY_POS_READ|KEY_POS_SEARCH| KEY_USR_VIEW|KEY_USR_READ|KEY_USR_SEARCH, 0, 0) < 0) - return log_error_errno(errno, "Failed to restrict invocation ID permission: %m"); + return log_unit_error_errno(u, errno, "Failed to restrict invocation ID permission: %m"); } } /* And now, make the keyring owned by the service's user */ if (uid_is_valid(uid) || gid_is_valid(gid)) if (keyctl(KEYCTL_CHOWN, keyring, uid, gid, 0) < 0) - return log_error_errno(errno, "Failed to change ownership of session keyring: %m"); + return log_unit_error_errno(u, errno, "Failed to change ownership of session keyring: %m"); /* When requested link the user keyring into the session keyring. */ if (context->keyring_mode == EXEC_KEYRING_SHARED) { @@ -2237,13 +2237,13 @@ static int setup_keyring( if (gid_is_valid(gid) && gid != saved_gid) { if (setregid(gid, -1) < 0) - return log_error_errno(errno, "Failed to change GID for user keyring: %m"); + return log_unit_error_errno(u, errno, "Failed to change GID for user keyring: %m"); } if (uid_is_valid(uid) && uid != saved_uid) { if (setreuid(uid, -1) < 0) { (void) setregid(saved_gid, -1); - return log_error_errno(errno, "Failed to change UID for user keyring: %m"); + return log_unit_error_errno(u, errno, "Failed to change UID for user keyring: %m"); } } @@ -2256,19 +2256,19 @@ static int setup_keyring( (void) setreuid(saved_uid, -1); (void) setregid(saved_gid, -1); - return log_error_errno(r, "Failed to link user keyring into session keyring: %m"); + return log_unit_error_errno(u, r, "Failed to link user keyring into session keyring: %m"); } if (uid_is_valid(uid) && uid != saved_uid) { if (setreuid(saved_uid, -1) < 0) { (void) setregid(saved_gid, -1); - return log_error_errno(errno, "Failed to change UID back for user keyring: %m"); + return log_unit_error_errno(u, errno, "Failed to change UID back for user keyring: %m"); } } if (gid_is_valid(gid) && gid != saved_gid) { if (setregid(saved_gid, -1) < 0) - return log_error_errno(errno, "Failed to change GID back for user keyring: %m"); + return log_unit_error_errno(u, errno, "Failed to change GID back for user keyring: %m"); } } From 82677ae4c7aeba0156785096fa8be09e06b70c90 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 26 Sep 2017 17:42:17 +0200 Subject: [PATCH 2/9] =?UTF-8?q?execute:=20downgrade=20a=20log=20message=20?= =?UTF-8?q?ERR=20=E2=86=92=20WARNING,=20since=20we=20proceed=20ignoring=20?= =?UTF-8?q?its=20result?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- src/core/execute.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/execute.c b/src/core/execute.c index 2baf824974..54e4043253 100644 --- a/src/core/execute.c +++ b/src/core/execute.c @@ -588,7 +588,7 @@ static int setup_output( case EXEC_OUTPUT_JOURNAL_AND_CONSOLE: r = connect_logger_as(unit, context, params, o, ident, fileno, uid, gid); if (r < 0) { - log_unit_error_errno(unit, r, "Failed to connect %s to the journal socket, ignoring: %m", fileno == STDOUT_FILENO ? "stdout" : "stderr"); + log_unit_warning_errno(unit, r, "Failed to connect %s to the journal socket, ignoring: %m", fileno == STDOUT_FILENO ? "stdout" : "stderr"); r = open_null_as(O_WRONLY, fileno); } else { struct stat st; From 7558e10c986ee42d1d107a912ae4a50065c6e8f0 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Mon, 25 Sep 2017 20:26:47 +0200 Subject: [PATCH 3/9] log: let's make use of the fact that our functions return the negative error code for log_oom() too --- src/basic/log.c | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/basic/log.c b/src/basic/log.c index 168c6c37ce..59bc16f64e 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -834,9 +834,8 @@ void log_assert_failed_return_realm( } int log_oom_internal(LogRealm realm, const char *file, int line, const char *func) { - log_internal_realm(LOG_REALM_PLUS_LEVEL(realm, LOG_ERR), - ENOMEM, file, line, func, "Out of memory."); - return -ENOMEM; + return log_internal_realm(LOG_REALM_PLUS_LEVEL(realm, LOG_ERR), + ENOMEM, file, line, func, "Out of memory."); } int log_format_iovec( From 16e4fd87c5be06d2b7a3b368205c8c5bab9df32a Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 26 Sep 2017 17:45:09 +0200 Subject: [PATCH 4/9] log: add a mode where we open the log fds for every single log message This we can then make use in execute.c to make error logging a bit less special when preparing for process execution, as we can still log but don't have any fds open continously. --- src/basic/log.c | 93 +++++++++++++++++++++++++++++++------------------ src/basic/log.h | 1 + 2 files changed, 60 insertions(+), 34 deletions(-) diff --git a/src/basic/log.c b/src/basic/log.c index 59bc16f64e..4f0fe54579 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -74,6 +74,7 @@ static bool show_location = false; static bool upgrade_syslog_to_journal = false; static bool always_reopen_console = false; +static bool open_when_needed = false; /* Akin to glibc's __abort_msg; which is private and we hence cannot * use here. */ @@ -585,6 +586,9 @@ int log_dispatch_internal( if ((level & LOG_FACMASK) == 0) level = log_facility | LOG_PRI(level); + if (open_when_needed) + log_open(); + do { char *e; int k = 0; @@ -640,6 +644,9 @@ int log_dispatch_internal( buffer = e; } while (buffer); + if (open_when_needed) + log_close(); + return -error; } @@ -910,38 +917,48 @@ int log_struct_internal( if ((level & LOG_FACMASK) == 0) level = log_facility | LOG_PRI(level); - if (IN_SET(log_target, LOG_TARGET_AUTO, - LOG_TARGET_JOURNAL_OR_KMSG, - LOG_TARGET_JOURNAL) && - journal_fd >= 0) { - char header[LINE_MAX]; - struct iovec iovec[17] = {}; - unsigned n = 0, i; - int r; - struct msghdr mh = { - .msg_iov = iovec, - }; - bool fallback = false; + if (IN_SET(log_target, + LOG_TARGET_AUTO, + LOG_TARGET_JOURNAL_OR_KMSG, + LOG_TARGET_JOURNAL)) { - /* If the journal is available do structured logging */ - log_do_header(header, sizeof(header), level, error, file, line, func, NULL, NULL, NULL, NULL); - iovec[n++] = IOVEC_MAKE_STRING(header); + if (open_when_needed) + log_open_journal(); - va_start(ap, format); - r = log_format_iovec(iovec, ELEMENTSOF(iovec), &n, true, error, format, ap); - if (r < 0) - fallback = true; - else { - mh.msg_iovlen = n; - (void) sendmsg(journal_fd, &mh, MSG_NOSIGNAL); + if (journal_fd >= 0) { + char header[LINE_MAX]; + struct iovec iovec[17] = {}; + unsigned n = 0, i; + int r; + struct msghdr mh = { + .msg_iov = iovec, + }; + bool fallback = false; + + /* If the journal is available do structured logging */ + log_do_header(header, sizeof(header), level, error, file, line, func, NULL, NULL, NULL, NULL); + iovec[n++] = IOVEC_MAKE_STRING(header); + + va_start(ap, format); + r = log_format_iovec(iovec, ELEMENTSOF(iovec), &n, true, error, format, ap); + if (r < 0) + fallback = true; + else { + mh.msg_iovlen = n; + (void) sendmsg(journal_fd, &mh, MSG_NOSIGNAL); + } + + va_end(ap); + for (i = 1; i < n; i += 2) + free(iovec[i].iov_base); + + if (!fallback) { + if (open_when_needed) + log_close(); + + return -error; + } } - - va_end(ap); - for (i = 1; i < n; i += 2) - free(iovec[i].iov_base); - - if (!fallback) - return -error; } /* Fallback if journal logging is not available or didn't work. */ @@ -968,8 +985,12 @@ int log_struct_internal( } va_end(ap); - if (!found) + if (!found) { + if (open_when_needed) + log_close(); + return -error; + } return log_dispatch_internal(level, error, file, line, func, NULL, NULL, NULL, NULL, buf + 8); } @@ -1220,10 +1241,6 @@ void log_received_signal(int level, const struct signalfd_siginfo *si) { } -void log_set_upgrade_syslog_to_journal(bool b) { - upgrade_syslog_to_journal = b; -} - int log_syntax_internal( const char *unit, int level, @@ -1271,6 +1288,14 @@ int log_syntax_internal( NULL); } +void log_set_upgrade_syslog_to_journal(bool b) { + upgrade_syslog_to_journal = b; +} + void log_set_always_reopen_console(bool b) { always_reopen_console = b; } + +void log_set_open_when_needed(bool b) { + open_when_needed = b; +} diff --git a/src/basic/log.h b/src/basic/log.h index e3fd3203d0..10a6032788 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -303,6 +303,7 @@ void log_received_signal(int level, const struct signalfd_siginfo *si); void log_set_upgrade_syslog_to_journal(bool b); void log_set_always_reopen_console(bool b); +void log_set_open_when_needed(bool b); int log_syntax_internal( const char *unit, From 2c027c62dd0f2daf3dd7e9d14313863ca90c9725 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 26 Sep 2017 17:45:32 +0200 Subject: [PATCH 5/9] execute: make use of the new logging mode in execute.c --- src/core/execute.c | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/src/core/execute.c b/src/core/execute.c index 54e4043253..edeb857e15 100644 --- a/src/core/execute.c +++ b/src/core/execute.c @@ -2466,11 +2466,13 @@ static int exec_child( if (params->idle_pipe) do_idle_pipe_dance(params->idle_pipe); - /* Close sockets very early to make sure we don't - * block init reexecution because it cannot bind its - * sockets */ + /* Close fds we don't need very early to make sure we don't block init reexecution because it cannot bind its + * sockets. Among the fds we close are the logging fds, and we want to keep them closed, so that we don't have + * any fds open we don't really want open during the transition. In order to make logging work, we switch the + * log subsystem into open_when_needed mode, so that it reopens the logs on every single log call. */ log_forget_fds(); + log_set_open_when_needed(true); n_fds = n_storage_fds + n_socket_fds; r = close_remaining_fds(params, runtime, dcreds, user_lookup_fd, socket_fd, fds, n_fds); From 86ffb3256030e8cf22ae17bebce77c0a7fb1637b Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 26 Sep 2017 17:41:53 +0200 Subject: [PATCH 6/9] execute: drop explicit log_open()/log_close() now that it is unnecessary --- src/core/execute.c | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/src/core/execute.c b/src/core/execute.c index edeb857e15..451a05b9de 100644 --- a/src/core/execute.c +++ b/src/core/execute.c @@ -1323,9 +1323,7 @@ static bool skip_seccomp_unavailable(const Unit* u, const char* msg) { if (is_seccomp_available()) return false; - log_open(); log_unit_debug(u, "SECCOMP features not detected in the kernel, skipping %s", msg); - log_close(); return true; } @@ -2109,10 +2107,8 @@ static int apply_mount_namespace( /* If we couldn't set up the namespace this is probably due to a * missing capability. In this case, silently proceeed. */ if (IN_SET(r, -EPERM, -EACCES)) { - log_open(); log_unit_debug_errno(u, r, "Failed to set up namespace, assuming containerized execution, ignoring: %m"); - log_close(); - r = 0; + return 0; } return r; From 12145637e9d40bc9c34d026440526ede0a4a0fb4 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 26 Sep 2017 17:47:27 +0200 Subject: [PATCH 7/9] execute: normalize logging in execute.c Now that logging can implicitly reopen the log streams when needed we can log errors without any special magic, hence let's normalize things, and log the same way we do everywhere else. --- src/core/execute.c | 272 ++++++++++++++++----------------------------- 1 file changed, 98 insertions(+), 174 deletions(-) diff --git a/src/core/execute.c b/src/core/execute.c index 451a05b9de..47d8aa3910 100644 --- a/src/core/execute.c +++ b/src/core/execute.c @@ -2399,8 +2399,7 @@ static int exec_child( unsigned n_socket_fds, char **files_env, int user_lookup_fd, - int *exit_status, - char **error_message) { + int *exit_status) { _cleanup_strv_free_ char **our_env = NULL, **pass_env = NULL, **accum_env = NULL, **final_argv = NULL; _cleanup_free_ char *mac_selinux_context_net = NULL, *home_buffer = NULL; @@ -2434,9 +2433,6 @@ static int exec_child( assert(context); assert(params); assert(exit_status); - assert(error_message); - /* We don't always set error_message, hence it must be initialized */ - assert(*error_message == NULL); rename_process_from_path(command->path); @@ -2454,9 +2450,7 @@ static int exec_child( r = reset_signal_mask(); if (r < 0) { *exit_status = EXIT_SIGNAL_MASK; - *error_message = strdup("Failed to set process signal mask"); - /* If strdup fails, here and below, we will just print the generic error message. */ - return r; + return log_unit_error_errno(unit, r, "Failed to set process signal mask: %m"); } if (params->idle_pipe) @@ -2474,15 +2468,13 @@ static int exec_child( r = close_remaining_fds(params, runtime, dcreds, user_lookup_fd, socket_fd, fds, n_fds); if (r < 0) { *exit_status = EXIT_FDS; - *error_message = strdup("Failed to close unwanted file descriptors"); - return r; + return log_unit_error_errno(unit, r, "Failed to close unwanted file descriptors: %m"); } if (!context->same_pgrp) if (setsid() < 0) { *exit_status = EXIT_SETSID; - *error_message = strdup("Failed to create new process session"); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to create new process session: %m"); } exec_context_tty_reset(context, params); @@ -2494,7 +2486,7 @@ static int exec_child( cmdline = exec_command_line(argv); if (!cmdline) { *exit_status = EXIT_MEMORY; - return -ENOMEM; + return log_oom(); } r = ask_for_confirmation(vc, unit, cmdline); @@ -2504,7 +2496,7 @@ static int exec_child( return 0; } *exit_status = EXIT_CONFIRM; - *error_message = strdup("Execution cancelled by the user"); + log_unit_error(unit, "Execution cancelled by the user"); return -ECANCELED; } } @@ -2514,27 +2506,24 @@ static int exec_child( /* Make sure we bypass our own NSS module for any NSS checks */ if (putenv((char*) "SYSTEMD_NSS_DYNAMIC_BYPASS=1") != 0) { *exit_status = EXIT_USER; - *error_message = strdup("Failed to update environment"); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to update environment: %m"); } r = dynamic_creds_realize(dcreds, &uid, &gid); if (r < 0) { *exit_status = EXIT_USER; - *error_message = strdup("Failed to update dynamic user credentials"); - return r; + return log_unit_error_errno(unit, r, "Failed to update dynamic user credentials: %m"); } if (!uid_is_valid(uid)) { *exit_status = EXIT_USER; - (void) asprintf(error_message, "UID validation failed for \""UID_FMT"\"", uid); - /* If asprintf fails, here and below, we will just print the generic error message. */ + log_unit_error(unit, "UID validation failed for \""UID_FMT"\"", uid); return -ESRCH; } if (!gid_is_valid(gid)) { *exit_status = EXIT_USER; - (void) asprintf(error_message, "GID validation failed for \""GID_FMT"\"", gid); + log_unit_error(unit, "GID validation failed for \""GID_FMT"\"", gid); return -ESRCH; } @@ -2545,15 +2534,13 @@ static int exec_child( r = get_fixed_user(context, &username, &uid, &gid, &home, &shell); if (r < 0) { *exit_status = EXIT_USER; - *error_message = strdup("Failed to determine user credentials"); - return r; + return log_unit_error_errno(unit, r, "Failed to determine user credentials: %m"); } r = get_fixed_group(context, &groupname, &gid); if (r < 0) { *exit_status = EXIT_GROUP; - *error_message = strdup("Failed to determine group credentials"); - return r; + return log_unit_error_errno(unit, r, "Failed to determine group credentials: %m"); } } @@ -2562,15 +2549,13 @@ static int exec_child( &supplementary_gids, &ngids); if (r < 0) { *exit_status = EXIT_GROUP; - *error_message = strdup("Failed to determine supplementary groups"); - return r; + return log_unit_error_errno(unit, r, "Failed to determine supplementary groups: %m"); } r = send_user_lookup(unit, user_lookup_fd, uid, gid); if (r < 0) { *exit_status = EXIT_USER; - *error_message = strdup("Failed to send user credentials to PID1"); - return r; + return log_unit_error_errno(unit, r, "Failed to send user credentials to PID1: %m"); } user_lookup_fd = safe_close(user_lookup_fd); @@ -2578,8 +2563,7 @@ static int exec_child( r = acquire_home(context, uid, &home, &home_buffer); if (r < 0) { *exit_status = EXIT_CHDIR; - *error_message = strdup("Failed to determine $HOME for user"); - return r; + return log_unit_error_errno(unit, r, "Failed to determine $HOME for user: %m"); } /* If a socket is connected to STDIN/STDOUT/STDERR, we @@ -2590,30 +2574,26 @@ static int exec_child( r = setup_input(context, params, socket_fd, named_iofds); if (r < 0) { *exit_status = EXIT_STDIN; - *error_message = strdup("Failed to set up standard input"); - return r; + return log_unit_error_errno(unit, r, "Failed to set up standard input: %m"); } r = setup_output(unit, context, params, STDOUT_FILENO, socket_fd, named_iofds, basename(command->path), uid, gid, &journal_stream_dev, &journal_stream_ino); if (r < 0) { *exit_status = EXIT_STDOUT; - *error_message = strdup("Failed to set up standard output"); - return r; + return log_unit_error_errno(unit, r, "Failed to set up standard output: %m"); } r = setup_output(unit, context, params, STDERR_FILENO, socket_fd, named_iofds, basename(command->path), uid, gid, &journal_stream_dev, &journal_stream_ino); if (r < 0) { *exit_status = EXIT_STDERR; - *error_message = strdup("Failed to set up standard error output"); - return r; + return log_unit_error_errno(unit, r, "Failed to set up standard error output: %m"); } if (params->cgroup_path) { r = cg_attach_everywhere(params->cgroup_supported, params->cgroup_path, 0, NULL, NULL); if (r < 0) { *exit_status = EXIT_CGROUP; - (void) asprintf(error_message, "Failed to attach to cgroup %s", params->cgroup_path); - return r; + return log_unit_error_errno(unit, r, "Failed to attach to cgroup %s: %m", params->cgroup_path); } } @@ -2627,22 +2607,18 @@ static int exec_child( sprintf(t, "%i", context->oom_score_adjust); r = write_string_file("/proc/self/oom_score_adj", t, 0); - if (r == -EPERM || r == -EACCES) { - log_open(); + if (IN_SET(r, -EPERM, -EACCES)) log_unit_debug_errno(unit, r, "Failed to adjust OOM setting, assuming containerized execution, ignoring: %m"); - log_close(); - } else if (r < 0) { + else if (r < 0) { *exit_status = EXIT_OOM_ADJUST; - *error_message = strdup("Failed to adjust OOM setting"); - return -errno; + return log_unit_error_errno(unit, r, "Failed to adjust OOM setting: %m"); } } if (context->nice_set) if (setpriority(PRIO_PROCESS, 0, context->nice) < 0) { *exit_status = EXIT_NICE; - *error_message = strdup("Failed to set up process scheduling priority (nice level)"); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to set up process scheduling priority (nice level): %m"); } if (context->cpu_sched_set) { @@ -2657,38 +2633,33 @@ static int exec_child( ¶m); if (r < 0) { *exit_status = EXIT_SETSCHEDULER; - *error_message = strdup("Failed to set up CPU scheduling"); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to set up CPU scheduling: %m"); } } if (context->cpuset) if (sched_setaffinity(0, CPU_ALLOC_SIZE(context->cpuset_ncpus), context->cpuset) < 0) { *exit_status = EXIT_CPUAFFINITY; - *error_message = strdup("Failed to set up CPU affinity"); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to set up CPU affinity: %m"); } if (context->ioprio_set) if (ioprio_set(IOPRIO_WHO_PROCESS, 0, context->ioprio) < 0) { *exit_status = EXIT_IOPRIO; - *error_message = strdup("Failed to set up IO scheduling priority"); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to set up IO scheduling priority: %m"); } if (context->timer_slack_nsec != NSEC_INFINITY) if (prctl(PR_SET_TIMERSLACK, context->timer_slack_nsec) < 0) { *exit_status = EXIT_TIMERSLACK; - *error_message = strdup("Failed to set up timer slack"); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to set up timer slack: %m"); } if (context->personality != PERSONALITY_INVALID) { r = safe_personality(context->personality); if (r < 0) { *exit_status = EXIT_PERSONALITY; - *error_message = strdup("Failed to set up execution domain (personality)"); - return r; + return log_unit_error_errno(unit, r, "Failed to set up execution domain (personality): %m"); } } @@ -2704,8 +2675,7 @@ static int exec_child( r = chown_terminal(STDIN_FILENO, uid); if (r < 0) { *exit_status = EXIT_STDIN; - *error_message = strdup("Failed to change ownership of terminal"); - return r; + return log_unit_error_errno(unit, r, "Failed to change ownership of terminal: %m"); } } @@ -2716,25 +2686,20 @@ static int exec_child( r = cg_set_task_access(SYSTEMD_CGROUP_CONTROLLER, params->cgroup_path, 0644, uid, gid); if (r < 0) { *exit_status = EXIT_CGROUP; - *error_message = strdup("Failed to adjust control group access"); - return r; + return log_unit_error_errno(unit, r, "Failed to adjust control group access: %m"); } - r = cg_set_group_access(SYSTEMD_CGROUP_CONTROLLER, params->cgroup_path, 0755, uid, gid); if (r < 0) { *exit_status = EXIT_CGROUP; - *error_message = strdup("Failed to adjust control group access"); - return r; + return log_unit_error_errno(unit, r, "Failed to adjust control group access: %m"); } } for (dt = 0; dt < _EXEC_DIRECTORY_MAX; dt++) { r = setup_exec_directory(context, params, uid, gid, dt, exit_status); - if (r < 0) { - *error_message = strdup("Failed to set up special execution directory"); - return r; - } + if (r < 0) + return log_unit_error_errno(unit, r, "Failed to set up special execution directory in %s: %m", params->prefix[dt]); } r = build_environment( @@ -2750,13 +2715,13 @@ static int exec_child( &our_env); if (r < 0) { *exit_status = EXIT_MEMORY; - return r; + return log_oom(); } r = build_pass_environment(context, &pass_env); if (r < 0) { *exit_status = EXIT_MEMORY; - return r; + return log_oom(); } accum_env = strv_env_merge(5, @@ -2768,7 +2733,7 @@ static int exec_child( NULL); if (!accum_env) { *exit_status = EXIT_MEMORY; - return -ENOMEM; + return log_oom(); } accum_env = strv_env_clean(accum_env); @@ -2777,8 +2742,7 @@ static int exec_child( r = setup_keyring(unit, context, params, uid, gid); if (r < 0) { *exit_status = EXIT_KEYRING; - *error_message = strdup("Failed to set up kernel keyring"); - return r; + return log_unit_error_errno(unit, r, "Failed to set up kernel keyring: %m"); } /* We need sandboxing if the caller asked us to apply it and the command isn't explicitly excepted from it */ @@ -2814,8 +2778,7 @@ static int exec_child( r = setup_pam(context->pam_name, username, uid, gid, context->tty_path, &accum_env, fds, n_fds); if (r < 0) { *exit_status = EXIT_PAM; - *error_message = strdup("Failed to set up PAM session"); - return r; + return log_unit_error_errno(unit, r, "Failed to set up PAM session: %m"); } } } @@ -2824,8 +2787,7 @@ static int exec_child( r = setup_netns(runtime->netns_storage_socket); if (r < 0) { *exit_status = EXIT_NETWORK; - *error_message = strdup("Failed to set up network namespacing"); - return r; + return log_unit_error_errno(unit, r, "Failed to set up network namespacing: %m"); } } @@ -2834,25 +2796,21 @@ static int exec_child( r = apply_mount_namespace(unit, command, context, params, runtime); if (r < 0) { *exit_status = EXIT_NAMESPACE; - *error_message = strdup("Failed to set up mount namespacing"); - return r; + return log_unit_error_errno(unit, r, "Failed to set up mount namespacing: %m"); } } /* Apply just after mount namespace setup */ r = apply_working_directory(context, params, home, needs_mount_namespace, exit_status); - if (r < 0) { - *error_message = strdup("Changing to the requested working directory failed"); - return r; - } + if (r < 0) + return log_unit_error_errno(unit, r, "Changing to the requested working directory failed: %m"); /* Drop groups as early as possbile */ if (needs_setuid) { r = enforce_groups(context, gid, supplementary_gids, ngids); if (r < 0) { - *error_message = strdup("Changing group credentials failed"); *exit_status = EXIT_GROUP; - return r; + return log_unit_error_errno(unit, r, "Changing group credentials failed: %m"); } } @@ -2861,9 +2819,8 @@ static int exec_child( if (use_selinux && params->selinux_context_net && socket_fd >= 0) { r = mac_selinux_get_child_mls_label(socket_fd, command->path, context->selinux_context, &mac_selinux_context_net); if (r < 0) { - *error_message = strdup("Failed to determine SELinux context"); *exit_status = EXIT_SELINUX_CONTEXT; - return r; + return log_unit_error_errno(unit, r, "Failed to determine SELinux context: %m"); } } #endif @@ -2871,9 +2828,8 @@ static int exec_child( if (context->private_users) { r = setup_private_users(uid, gid); if (r < 0) { - *error_message = strdup("Failed to set up user namespacing"); *exit_status = EXIT_USER; - return r; + return log_unit_error_errno(unit, r, "Failed to set up user namespacing: %m"); } } } @@ -2887,9 +2843,8 @@ static int exec_child( if (r >= 0) r = flags_fds(fds, n_storage_fds, n_socket_fds, context->non_blocking); if (r < 0) { - *error_message = strdup("Failed to adjust passed file descriptors"); *exit_status = EXIT_FDS; - return r; + return log_unit_error_errno(unit, r, "Failed to adjust passed file descriptors: %m"); } secure_bits = context->secure_bits; @@ -2904,18 +2859,16 @@ static int exec_child( r = setrlimit_closest(i, context->rlimit[i]); if (r < 0) { - *error_message = strdup("Failed to adjust resource limits"); *exit_status = EXIT_LIMITS; - return r; + return log_unit_error_errno(unit, r, "Failed to adjust resource limit %s: %m", rlimit_to_string(i)); } } /* Set the RTPRIO resource limit to 0, but only if nothing else was explicitly requested. */ if (context->restrict_realtime && !context->rlimit[RLIMIT_RTPRIO]) { if (setrlimit(RLIMIT_RTPRIO, &RLIMIT_MAKE_CONST(0)) < 0) { - *error_message = strdup("Failed to adjust RLIMIT_RTPRIO resource limit"); *exit_status = EXIT_LIMITS; - return -errno; + return log_unit_error_errno(unit, errno, "Failed to adjust RLIMIT_RTPRIO resource limit: %m"); } } @@ -2932,8 +2885,7 @@ static int exec_child( r = capability_bounding_set_drop(bset, false); if (r < 0) { *exit_status = EXIT_CAPABILITIES; - *error_message = strdup("Failed to drop capabilities"); - return r; + return log_unit_error_errno(unit, r, "Failed to drop capabilities: %m"); } } @@ -2944,8 +2896,7 @@ static int exec_child( r = capability_ambient_set_apply(context->capability_ambient_set, true); if (r < 0) { *exit_status = EXIT_CAPABILITIES; - *error_message = strdup("Failed to apply ambient capabilities (before UID change)"); - return r; + return log_unit_error_errno(unit, r, "Failed to apply ambient capabilities (before UID change): %m"); } } } @@ -2955,8 +2906,7 @@ static int exec_child( r = enforce_user(context, uid); if (r < 0) { *exit_status = EXIT_USER; - (void) asprintf(error_message, "Failed to change UID to "UID_FMT, uid); - return r; + return log_unit_error_errno(unit, r, "Failed to change UID to " UID_FMT ": %m", uid); } if (!needs_ambient_hack && @@ -2966,8 +2916,7 @@ static int exec_child( r = capability_ambient_set_apply(context->capability_ambient_set, false); if (r < 0) { *exit_status = EXIT_CAPABILITIES; - *error_message = strdup("Failed to apply ambient capabilities (after UID change)"); - return r; + return log_unit_error_errno(unit, r, "Failed to apply ambient capabilities (after UID change): %m"); } /* If we were asked to change user and ambient capabilities @@ -2996,8 +2945,7 @@ static int exec_child( r = setexeccon(exec_context); if (r < 0) { *exit_status = EXIT_SELINUX_CONTEXT; - (void) asprintf(error_message, "Failed to change SELinux context to %s", exec_context); - return r; + return log_unit_error_errno(unit, r, "Failed to change SELinux context to %s: %m", exec_context); } } } @@ -3008,8 +2956,7 @@ static int exec_child( r = setup_smack(context, command); if (r < 0) { *exit_status = EXIT_SMACK_PROCESS_LABEL; - *error_message = strdup("Failed to set SMACK process label"); - return r; + return log_unit_error_errno(unit, r, "Failed to set SMACK process label: %m"); } } #endif @@ -3019,10 +2966,7 @@ static int exec_child( r = aa_change_onexec(context->apparmor_profile); if (r < 0 && !context->apparmor_profile_ignore) { *exit_status = EXIT_APPARMOR_PROFILE; - (void) asprintf(error_message, - "Failed to prepare AppArmor profile change to %s", - context->apparmor_profile); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to prepare AppArmor profile change to %s: %m", context->apparmor_profile); } } #endif @@ -3032,79 +2976,68 @@ static int exec_child( if (prctl(PR_GET_SECUREBITS) != secure_bits) if (prctl(PR_SET_SECUREBITS, secure_bits) < 0) { *exit_status = EXIT_SECUREBITS; - *error_message = strdup("Failed to set process secure bits"); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to set process secure bits: %m"); } if (context_has_no_new_privileges(context)) if (prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) < 0) { *exit_status = EXIT_NO_NEW_PRIVILEGES; - *error_message = strdup("Failed to disable new privileges"); - return -errno; + return log_unit_error_errno(unit, errno, "Failed to disable new privileges: %m"); } #ifdef HAVE_SECCOMP r = apply_address_families(unit, context); if (r < 0) { *exit_status = EXIT_ADDRESS_FAMILIES; - *error_message = strdup("Failed to restrict address families"); - return r; + return log_unit_error_errno(unit, r, "Failed to restrict address families: %m"); } r = apply_memory_deny_write_execute(unit, context); if (r < 0) { *exit_status = EXIT_SECCOMP; - *error_message = strdup("Failed to disable writing to executable memory"); - return r; + return log_unit_error_errno(unit, r, "Failed to disable writing to executable memory: %m"); } r = apply_restrict_realtime(unit, context); if (r < 0) { *exit_status = EXIT_SECCOMP; - *error_message = strdup("Failed to apply realtime restrictions"); - return r; + return log_unit_error_errno(unit, r, "Failed to apply realtime restrictions: %m"); } r = apply_restrict_namespaces(unit, context); if (r < 0) { *exit_status = EXIT_SECCOMP; - *error_message = strdup("Failed to apply namespace restrictions"); - return r; + return log_unit_error_errno(unit, r, "Failed to apply namespace restrictions: %m"); } r = apply_protect_sysctl(unit, context); if (r < 0) { *exit_status = EXIT_SECCOMP; - *error_message = strdup("Failed to apply sysctl restrictions"); - return r; + return log_unit_error_errno(unit, r, "Failed to apply sysctl restrictions: %m"); } r = apply_protect_kernel_modules(unit, context); if (r < 0) { *exit_status = EXIT_SECCOMP; - *error_message = strdup("Failed to apply module loading restrictions"); - return r; + return log_unit_error_errno(unit, r, "Failed to apply module loading restrictions: %m"); } r = apply_private_devices(unit, context); if (r < 0) { *exit_status = EXIT_SECCOMP; - *error_message = strdup("Failed to set up private devices"); - return r; + return log_unit_error_errno(unit, r, "Failed to set up private devices: %m"); } r = apply_syscall_archs(unit, context); if (r < 0) { *exit_status = EXIT_SECCOMP; - *error_message = strdup("Failed to apply syscall architecture restrictions"); - return r; + return log_unit_error_errno(unit, r, "Failed to apply syscall architecture restrictions: %m"); } r = apply_lock_personality(unit, context); if (r < 0) { *exit_status = EXIT_SECCOMP; - *error_message = strdup("Failed to lock personalities"); - return r; + return log_unit_error_errno(unit, r, "Failed to lock personalities: %m"); } /* This really should remain the last step before the execve(), to make sure our own code is unaffected @@ -3112,8 +3045,7 @@ static int exec_child( r = apply_syscall_filter(unit, context, needs_ambient_hack); if (r < 0) { *exit_status = EXIT_SECCOMP; - *error_message = strdup("Failed to apply system call filters"); - return r; + return log_unit_error_errno(unit, r, "Failed to apply system call filters: %m"); } #endif } @@ -3124,7 +3056,7 @@ static int exec_child( ee = strv_env_delete(accum_env, 1, context->unset_environment); if (!ee) { *exit_status = EXIT_MEMORY; - return -ENOMEM; + return log_oom(); } strv_free(accum_env); @@ -3134,8 +3066,7 @@ static int exec_child( final_argv = replace_env_argv(argv, accum_env); if (!final_argv) { *exit_status = EXIT_MEMORY; - *error_message = strdup("Failed to prepare process arguments"); - return -ENOMEM; + return log_oom(); } if (_unlikely_(log_get_max_level() >= LOG_DEBUG)) { @@ -3143,20 +3074,33 @@ static int exec_child( line = exec_command_line(final_argv); if (line) { - log_open(); log_struct(LOG_DEBUG, "EXECUTABLE=%s", command->path, LOG_UNIT_MESSAGE(unit, "Executing: %s", line), LOG_UNIT_ID(unit), LOG_UNIT_INVOCATION_ID(unit), NULL); - log_close(); } } execve(command->path, final_argv, accum_env); + + if (errno == ENOENT && (command->flags & EXEC_COMMAND_IGNORE_FAILURE)) { + + log_struct_errno(LOG_INFO, errno, + "MESSAGE_ID=" SD_MESSAGE_SPAWN_FAILED_STR, + LOG_UNIT_ID(unit), + LOG_UNIT_INVOCATION_ID(unit), + LOG_UNIT_MESSAGE(unit, "Executable %s missing, skipping: %m", + command->path), + "EXECUTABLE=%s", command->path, + NULL); + + return 0; + } + *exit_status = EXIT_EXEC; - return -errno; + return log_unit_error_errno(unit, errno, "Failed to execute command: %m"); } int exec_spawn(Unit *unit, @@ -3224,13 +3168,13 @@ int exec_spawn(Unit *unit, LOG_UNIT_ID(unit), LOG_UNIT_INVOCATION_ID(unit), NULL); + pid = fork(); if (pid < 0) return log_unit_error_errno(unit, errno, "Failed to fork: %m"); if (pid == 0) { - int exit_status; - _cleanup_free_ char *error_message = NULL; + int exit_status = EXIT_SUCCESS; r = exec_child(unit, command, @@ -3246,38 +3190,18 @@ int exec_spawn(Unit *unit, n_socket_fds, files_env, unit->manager->user_lookup_fds[1], - &exit_status, - &error_message); + &exit_status); + if (r < 0) { - log_open(); - if (error_message) - log_struct_errno(LOG_ERR, r, - "MESSAGE_ID=" SD_MESSAGE_SPAWN_FAILED_STR, - LOG_UNIT_ID(unit), - LOG_UNIT_INVOCATION_ID(unit), - LOG_UNIT_MESSAGE(unit, "%s: %m", - error_message), - "EXECUTABLE=%s", command->path, - NULL); - else if (r == -ENOENT && (command->flags & EXEC_COMMAND_IGNORE_FAILURE)) - log_struct_errno(LOG_INFO, r, - "MESSAGE_ID=" SD_MESSAGE_SPAWN_FAILED_STR, - LOG_UNIT_ID(unit), - LOG_UNIT_INVOCATION_ID(unit), - LOG_UNIT_MESSAGE(unit, "Skipped spawning %s: %m", - command->path), - "EXECUTABLE=%s", command->path, - NULL); - else - log_struct_errno(LOG_ERR, r, - "MESSAGE_ID=" SD_MESSAGE_SPAWN_FAILED_STR, - LOG_UNIT_ID(unit), - LOG_UNIT_INVOCATION_ID(unit), - LOG_UNIT_MESSAGE(unit, "Failed at step %s spawning %s: %m", - exit_status_to_string(exit_status, EXIT_STATUS_SYSTEMD), - command->path), - "EXECUTABLE=%s", command->path, - NULL); + log_struct_errno(LOG_ERR, r, + "MESSAGE_ID=" SD_MESSAGE_SPAWN_FAILED_STR, + LOG_UNIT_ID(unit), + LOG_UNIT_INVOCATION_ID(unit), + LOG_UNIT_MESSAGE(unit, "Failed at step %s spawning %s: %m", + exit_status_to_string(exit_status, EXIT_STATUS_SYSTEMD), + command->path), + "EXECUTABLE=%s", command->path, + NULL); } _exit(exit_status); From 40a80078d24230f668a22df63d866643825486ec Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 26 Sep 2017 17:52:25 +0200 Subject: [PATCH 8/9] execute: let's close glibc syslog channels too Just in case something opened them, let's make sure glibc invalidates them too. Thankfully so far no library opened log channels behind our back, at least as far as I know, hence this is actually a NOP, but let's better be safe than sorry. --- src/core/execute.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/core/execute.c b/src/core/execute.c index 47d8aa3910..cd4b9f8eb2 100644 --- a/src/core/execute.c +++ b/src/core/execute.c @@ -2464,6 +2464,9 @@ static int exec_child( log_forget_fds(); log_set_open_when_needed(true); + /* In case anything used libc syslog(), close this here, too */ + closelog(); + n_fds = n_storage_fds + n_socket_fds; r = close_remaining_fds(params, runtime, dcreds, user_lookup_fd, socket_fd, fds, n_fds); if (r < 0) { From 81f84b33dae12842dcbf935e3e0f94b974df9c8d Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 26 Sep 2017 18:00:38 +0200 Subject: [PATCH 9/9] update TODO --- TODO | 6 ------ 1 file changed, 6 deletions(-) diff --git a/TODO b/TODO index b638ab95c8..dacce6cee0 100644 --- a/TODO +++ b/TODO @@ -26,12 +26,6 @@ Features: * replace all uses of fgets() + LINE_MAX by read_line() -* fix logging in execute.c: extend log.c to have an optional mode where - log_open() is implicitly done before each log line and log_close() right - after. This way we don't have open fds around but logs will still - work. Because it is slow this mode should used exclusively in the execute.c - case. - * set IPAddressDeny=any on all services that shouldn't do networking (possibly combined with IPAddressAllow=localhost).