From 843d2643849a1ec63034012c8fe50bfaad23190b Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Sat, 15 May 2010 17:25:08 +0200 Subject: [PATCH] log: rework logging logic so that we don't keep /dev/console open --- log.c | 246 ++++++++++++++++++++++++++++++++++++++------------------- log.h | 14 ++-- main.c | 98 ++++++++++------------- unit.c | 2 +- util.c | 18 +++++ util.h | 2 + 6 files changed, 234 insertions(+), 146 deletions(-) diff --git a/log.c b/log.c index e1c9ed7471..5d17955e7e 100644 --- a/log.c +++ b/log.c @@ -37,6 +37,7 @@ static LogTarget log_target = LOG_TARGET_CONSOLE; static int log_max_level = LOG_DEBUG; +static int console_fd = STDERR_FILENO; static int syslog_fd = -1; static int kmsg_fd = -1; @@ -44,26 +45,52 @@ static int kmsg_fd = -1; * use here. */ static char *log_abort_msg = NULL; -void log_close_kmsg(void) { +void log_close_console(void) { - if (kmsg_fd >= 0) { - close_nointr_nofail(kmsg_fd); - kmsg_fd = -1; + if (console_fd < 0) + return; + + if (getpid() == 1 || console_fd != STDERR_FILENO) { + close_nointr_nofail(console_fd); + console_fd = -1; } } -int log_open_kmsg(void) { +static int log_open_console(void) { - if (log_target != LOG_TARGET_KMSG) { - log_close_kmsg(); + if (console_fd >= 0) return 0; - } + + if (getpid() == 1) { + + if ((console_fd = open_terminal("/dev/console", O_WRONLY|O_NOCTTY|O_CLOEXEC)) < 0) { + log_error("Failed to open /dev/console for logging: %s", strerror(-console_fd)); + return console_fd; + } + + log_info("Succesfully opened /dev/console for logging."); + } else + console_fd = STDERR_FILENO; + + return 0; +} + +void log_close_kmsg(void) { + + if (kmsg_fd < 0) + return; + + close_nointr_nofail(kmsg_fd); + kmsg_fd = -1; +} + +static int log_open_kmsg(void) { if (kmsg_fd >= 0) return 0; if ((kmsg_fd = open("/dev/kmsg", O_WRONLY|O_NOCTTY|O_CLOEXEC)) < 0) { - log_info("Failed to open syslog for logging: %s", strerror(errno)); + log_info("Failed to open /dev/kmsg for logging: %s", strerror(errno)); return -errno; } @@ -74,13 +101,14 @@ int log_open_kmsg(void) { void log_close_syslog(void) { - if (syslog_fd >= 0) { - close_nointr_nofail(syslog_fd); - syslog_fd = -1; - } + if (syslog_fd < 0) + return; + + close_nointr_nofail(syslog_fd); + syslog_fd = -1; } -int log_open_syslog(void) { +static int log_open_syslog(void) { union { struct sockaddr sa; struct sockaddr_un un; @@ -88,24 +116,20 @@ int log_open_syslog(void) { struct timeval tv; int r; - if (log_target != LOG_TARGET_SYSLOG) { - log_close_syslog(); - return 0; - } - if (syslog_fd >= 0) return 0; - if ((syslog_fd = socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0)) < 0) - return -errno; + if ((syslog_fd = socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0)) < 0) { + r = -errno; + goto fail; + } /* Make sure we don't block for more than 5s when talking to * syslog */ timeval_store(&tv, SYSLOG_TIMEOUT_USEC); if (setsockopt(syslog_fd, SOL_SOCKET, SO_SNDTIMEO, &tv, sizeof(tv)) < 0) { r = -errno; - log_close_syslog(); - return r; + goto fail; } zero(sa); @@ -114,15 +138,45 @@ int log_open_syslog(void) { if (connect(syslog_fd, &sa.sa, sizeof(sa)) < 0) { r = -errno; - log_close_syslog(); - - log_info("Failed to open syslog for logging: %s", strerror(-r)); - return r; + goto fail; } log_info("Succesfully opened syslog for logging."); return 0; + +fail: + log_close_syslog(); + log_info("Failed to open syslog for logging: %s", strerror(-r)); + return r; +} + +int log_open(void) { + int r; + + /* If we don't use the console we close it here, to not get + * killed by SAK. If we don't use syslog we close it here so + * that we are not confused by somebody deleting the socket in + * the fs. If we don't use /dev/kmsg we still keep it open, + * because there is no reason to close it. */ + + if (log_target == LOG_TARGET_SYSLOG_OR_KMSG || + log_target == LOG_TARGET_SYSLOG) + if ((r = log_open_syslog()) >= 0) { + log_close_console(); + return r; + } + + if (log_target == LOG_TARGET_SYSLOG_OR_KMSG || + log_target == LOG_TARGET_KMSG) + if ((r = log_open_kmsg()) >= 0) { + log_close_syslog(); + log_close_console(); + return r; + } + + log_close_syslog(); + return log_open_console(); } void log_set_target(LogTarget target) { @@ -138,27 +192,39 @@ void log_set_max_level(int level) { log_max_level = level; } -static void write_to_console( +static int write_to_console( int level, const char*file, int line, const char *func, - const char *format, - va_list ap) { + const char *buffer) { - const char *prefix, *suffix; + char location[64]; + struct iovec iovec[5]; + unsigned n = 0; + bool highlight; - if (LOG_PRI(level) <= LOG_ERR) { - prefix = "\x1B[1;31m"; - suffix = "\x1B[0m"; - } else { - prefix = ""; - suffix = ""; - } + if (console_fd < 0) + return 0; - fprintf(stderr, "(%s:%u) %s", file, line, prefix); - vfprintf(stderr, format, ap); - fprintf(stderr, "%s\n", suffix); + snprintf(location, sizeof(location), "(%s:%u) ", file, line); + char_array_0(location); + + highlight = LOG_PRI(level) <= LOG_ERR; + + zero(iovec); + IOVEC_SET_STRING(iovec[n++], location); + if (highlight) + IOVEC_SET_STRING(iovec[n++], "\x1B[1;31m"); + IOVEC_SET_STRING(iovec[n++], buffer); + if (highlight) + IOVEC_SET_STRING(iovec[n++], "\x1B[0m"); + IOVEC_SET_STRING(iovec[n++], "\n"); + + if (writev(console_fd, iovec, n) < 0) + return -errno; + + return 1; } static int write_to_syslog( @@ -166,18 +232,16 @@ static int write_to_syslog( const char*file, int line, const char *func, - const char *format, - va_list ap) { + const char *buffer) { char header_priority[16], header_time[64], header_pid[16]; - char buffer[LOG_BUFFER_MAX]; struct iovec iovec[5]; struct msghdr msghdr; time_t t; struct tm *tm; if (syslog_fd < 0) - return -EIO; + return 0; snprintf(header_priority, sizeof(header_priority), "<%i>", LOG_MAKEPRI(LOG_DAEMON, LOG_PRI(level))); char_array_0(header_priority); @@ -192,9 +256,6 @@ static int write_to_syslog( snprintf(header_pid, sizeof(header_pid), "[%llu]: ", (unsigned long long) getpid()); char_array_0(header_pid); - vsnprintf(buffer, sizeof(buffer), format, ap); - char_array_0(buffer); - zero(iovec); IOVEC_SET_STRING(iovec[0], header_priority); IOVEC_SET_STRING(iovec[1], header_time); @@ -209,7 +270,7 @@ static int write_to_syslog( if (sendmsg(syslog_fd, &msghdr, 0) < 0) return -errno; - return 0; + return 1; } static int write_to_kmsg( @@ -217,15 +278,13 @@ static int write_to_kmsg( const char*file, int line, const char *func, - const char *format, - va_list ap) { + const char *buffer) { char header_priority[16], header_pid[16]; - char buffer[LOG_BUFFER_MAX]; struct iovec iovec[5]; if (kmsg_fd < 0) - return -EIO; + return 0; snprintf(header_priority, sizeof(header_priority), "<%i>", LOG_PRI(level)); char_array_0(header_priority); @@ -233,57 +292,77 @@ static int write_to_kmsg( snprintf(header_pid, sizeof(header_pid), "[%llu]: ", (unsigned long long) getpid()); char_array_0(header_pid); - vsnprintf(buffer, sizeof(buffer), format, ap); - char_array_0(buffer); - zero(iovec); IOVEC_SET_STRING(iovec[0], header_priority); IOVEC_SET_STRING(iovec[1], __progname); IOVEC_SET_STRING(iovec[2], header_pid); IOVEC_SET_STRING(iovec[3], buffer); - IOVEC_SET_STRING(iovec[4], (char*) "\n"); + IOVEC_SET_STRING(iovec[4], "\n"); if (writev(kmsg_fd, iovec, ELEMENTSOF(iovec)) < 0) return -errno; - return 0; + return 1; } -#define LOG_DISPATCH(level,file,line,func,format) \ - do { \ - va_list _ap; \ - bool written = false; \ - if (log_target == LOG_TARGET_KMSG) { \ - va_start(_ap, format); \ - written = write_to_kmsg(level, file, line, func, format, _ap) >= 0; \ - va_end(_ap); \ - } else if (log_target == LOG_TARGET_SYSLOG) { \ - va_start(_ap, format); \ - written = write_to_syslog(level, file, line, func, format, _ap) >= 0; \ - va_end(_ap); \ - } \ - if (!written) { \ - va_start(_ap, format); \ - write_to_console(level, file, line, func, format, _ap); \ - va_end(_ap); \ - } \ - } while (false) +static int log_dispatch( + int level, + const char*file, + int line, + const char *func, + const char *buffer) { -void log_meta( + int r; + + if (log_target == LOG_TARGET_SYSLOG_OR_KMSG || + log_target == LOG_TARGET_SYSLOG) { + + if ((r = write_to_syslog(level, file, line, func, buffer)) < 0) { + log_close_syslog(); + log_open_kmsg(); + } else if (r > 0) + return r; + } + + if (log_target == LOG_TARGET_SYSLOG_OR_KMSG || + log_target == LOG_TARGET_KMSG) { + + if ((r = write_to_kmsg(level, file, line, func, buffer)) < 0) { + log_close_kmsg(); + log_open_console(); + } else if (r > 0) + return r; + } + + return write_to_console(level, file, line, func, buffer); +} + +int log_meta( int level, const char*file, int line, const char *func, const char *format, ...) { - int saved_errno; + char buffer[LOG_BUFFER_MAX]; + int saved_errno, r; + va_list ap; if (_likely(LOG_PRI(level) > log_max_level)) - return; + return 0; saved_errno = errno; - LOG_DISPATCH(level, file, line, func, format); + + va_start(ap, format); + vsnprintf(buffer, sizeof(buffer), format, ap); + va_end(ap); + + char_array_0(buffer); + + r = log_dispatch(level, file, line, func, buffer); errno = saved_errno; + + return r; } void log_assert( @@ -293,8 +372,8 @@ void log_assert( const char *format, ...) { static char buffer[LOG_BUFFER_MAX]; - va_list ap; int saved_errno = errno; + va_list ap; va_start(ap, format); vsnprintf(buffer, sizeof(buffer), format, ap); @@ -303,7 +382,7 @@ void log_assert( char_array_0(buffer); log_abort_msg = buffer; - LOG_DISPATCH(LOG_CRIT, file, line, func, format); + log_dispatch(LOG_CRIT, file, line, func, buffer); abort(); /* If the user chose to ignore this SIGABRT, we are happy to go on, as if nothing happened. */ @@ -354,6 +433,7 @@ static const char *const log_target_table[] = { [LOG_TARGET_CONSOLE] = "console", [LOG_TARGET_SYSLOG] = "syslog", [LOG_TARGET_KMSG] = "kmsg", + [LOG_TARGET_SYSLOG_OR_KMSG] = "syslog-or-kmsg", }; DEFINE_STRING_TABLE_LOOKUP(log_target, LogTarget); diff --git a/log.h b/log.h index 0fc1834f6f..6df1d59961 100644 --- a/log.h +++ b/log.h @@ -26,10 +26,13 @@ #include "macro.h" +/* If set to SYSLOG and /dev/log can not be opened we fall back to + * KSMG. If KMSG fails, we fall back to CONSOLE */ typedef enum LogTarget{ LOG_TARGET_CONSOLE, - LOG_TARGET_SYSLOG, LOG_TARGET_KMSG, + LOG_TARGET_SYSLOG, + LOG_TARGET_SYSLOG_OR_KMSG, _LOG_TARGET_MAX, _LOG_TARGET_INVALID = -1 } LogTarget; @@ -43,14 +46,15 @@ int log_set_max_level_from_string(const char *e); LogTarget log_get_target(void); int log_get_max_level(void); -void log_close_kmsg(void); -int log_open_kmsg(void); +int log_open(void); + void log_close_syslog(void); -int log_open_syslog(void); +void log_close_kmsg(void); +void log_close_console(void); void log_parse_environment(void); -void log_meta( +int log_meta( int level, const char*file, int line, diff --git a/main.c b/main.c index 1f407dce21..bba2975e46 100644 --- a/main.c +++ b/main.c @@ -136,23 +136,18 @@ _noreturn static void crash(int sig) { if ((pid = fork()) < 0) log_error("Failed to fork off crash shell: %s", strerror(errno)); else if (pid == 0) { - int fd; + int fd, r; if ((fd = acquire_terminal("/dev/console", false, true)) < 0) { log_error("Failed to acquire terminal: %s", strerror(-fd)); _exit(1); } - if (dup2(fd, STDIN_FILENO) < 0 || - dup2(fd, STDOUT_FILENO) < 0 || - dup2(fd, STDERR_FILENO) < 0) { - log_error("Failed to duplicate terminal fd: %s", strerror(errno)); + if ((r = make_stdio(fd)) < 0) { + log_error("Failed to duplicate terminal fd: %s", strerror(-r)); _exit(1); } - if (fd >= 3) - close_nointr_nofail(fd); - execl("/bin/sh", "/bin/sh", NULL); log_error("execl() failed: %s", strerror(errno)); @@ -182,51 +177,40 @@ static void install_crash_handler(void) { assert_se(sigaction(SIGABRT, &sa, NULL) == 0); } -static int console_setup(bool do_reset) { - int tty_fd = -1, null_fd = -1, r = 0; +static int make_null_stdio(void) { + int null_fd, r; - /* If we are init, we connect stdout/stderr to /dev/console - * and stdin to /dev/null and make sure we don't have a - * controlling tty. */ + if ((null_fd = open("/dev/null", O_RDWR)) < 0) { + log_error("Failed to open /dev/null: %m"); + return -errno; + } + + if ((r = make_stdio(null_fd)) < 0) + log_warning("Failed to dup2() device: %s", strerror(-r)); + + return r; +} + +static int console_setup(bool do_reset) { + int tty_fd, r; + + /* If we are init, we connect stdin/stdout/stderr to /dev/null + * and make sure we don't have a controlling tty. */ release_terminal(); - if ((tty_fd = open_terminal("/dev/console", O_WRONLY|O_NOCTTY)) < 0) { + if (!do_reset) + return 0; + + if ((tty_fd = open_terminal("/dev/console", O_WRONLY|O_NOCTTY|O_CLOEXEC)) < 0) { log_error("Failed to open /dev/console: %s", strerror(-tty_fd)); - r = -tty_fd; - goto finish; + return -tty_fd; } - if ((null_fd = open("/dev/null", O_RDONLY)) < 0) { - log_error("Failed to open /dev/null: %m"); - r = -errno; - goto finish; - } - - assert(tty_fd >= 3); - assert(null_fd >= 3); - - if (do_reset) - if (reset_terminal(tty_fd) < 0) - log_error("Failed to reset /dev/console: %m"); - - if (dup2(tty_fd, STDOUT_FILENO) < 0 || - dup2(tty_fd, STDERR_FILENO) < 0 || - dup2(null_fd, STDIN_FILENO) < 0) { - log_error("Failed to dup2() device: %m"); - r = -errno; - goto finish; - } - - r = 0; - -finish: - if (tty_fd >= 0) - close_nointr_nofail(tty_fd); - - if (null_fd >= 0) - close_nointr_nofail(null_fd); + if ((r = reset_terminal(tty_fd)) < 0) + log_error("Failed to reset /dev/console: %s", strerror(-r)); + close_nointr_nofail(tty_fd); return r; } @@ -499,7 +483,7 @@ static int help(void) { " -h --help Show this help\n" " --default=UNIT Set default unit\n" " --log-level=LEVEL Set log level\n" - " --log-target=TARGET Set log target (console, syslog, kmsg)\n" + " --log-target=TARGET Set log target (console, syslog, kmsg, syslog-or-kmsg)\n" " --running-as=AS Set running as (init, system, session)\n" " --test Determine startup sequence, dump it and exit\n" " --dump-configuration-items Dump understood unit configuration items\n" @@ -571,11 +555,10 @@ int main(int argc, char *argv[]) { FDSet *fds = NULL; bool reexecute = false; - if (getpid() == 1) + if (getpid() == 1) { running_as = MANAGER_INIT; - else if (getuid() == 0) - running_as = MANAGER_SYSTEM; - else + log_set_target(LOG_TARGET_SYSLOG_OR_KMSG); + } else running_as = MANAGER_SESSION; if (set_default_unit(SPECIAL_DEFAULT_TARGET) < 0) @@ -640,17 +623,18 @@ int main(int argc, char *argv[]) { umask(0); } - /* Reset the console, but only if this is really init and we - * are freshly booted */ - if (running_as == MANAGER_INIT && action == ACTION_RUN) - console_setup(getpid() == 1 && !serialization); - /* Make sure D-Bus doesn't fiddle with the SIGPIPE handlers */ dbus_connection_set_change_sigpipe(FALSE); + /* Reset the console, but only if this is really init and we + * are freshly booted */ + if (running_as != MANAGER_SESSION && action == ACTION_RUN) { + console_setup(getpid() == 1 && !serialization); + make_null_stdio(); + } + /* Open the logging devices, if possible and necessary */ - log_open_syslog(); - log_open_kmsg(); + log_open(); /* Make sure we leave a core dump without panicing the * kernel. */ diff --git a/unit.c b/unit.c index 7779753591..1757af317d 100644 --- a/unit.c +++ b/unit.c @@ -1027,7 +1027,7 @@ void unit_notify(Unit *u, UnitActiveState os, UnitActiveState ns) { /* The syslog daemon just might have become * available, hence try to connect to it, if * we aren't yet connected. */ - log_open_syslog(); + log_open(); if (u->meta.type == UNIT_MOUNT) /* Another directory became available, let's diff --git a/util.c b/util.c index f8b3f44ad1..5df811d038 100644 --- a/util.c +++ b/util.c @@ -1890,6 +1890,24 @@ int parse_usec(const char *t, usec_t *usec) { return 0; } +int make_stdio(int fd) { + int r, s, t; + + assert(fd >= 0); + + r = dup2(fd, STDIN_FILENO); + s = dup2(fd, STDOUT_FILENO); + t = dup2(fd, STDERR_FILENO); + + if (fd >= 3) + close_nointr_nofail(fd); + + if (r < 0 || s < 0 || t < 0) + return -errno; + + return 0; +} + static const char *const ioprio_class_table[] = { [IOPRIO_CLASS_NONE] = "none", [IOPRIO_CLASS_RT] = "realtime", diff --git a/util.h b/util.h index b9eb3602c8..ba27c759e8 100644 --- a/util.h +++ b/util.h @@ -179,6 +179,8 @@ bool chars_intersect(const char *a, const char *b); char *format_timestamp(char *buf, size_t l, usec_t t); +int make_stdio(int fd); + #define DEFINE_STRING_TABLE_LOOKUP(name,type) \ const char *name##_to_string(type i) { \ if (i < 0 || i >= (type) ELEMENTSOF(name##_table)) \