log: rework logging logic so that we don't keep /dev/console open

6 files changed, 232 insertions, 144 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 (console_fd < 0)
+                return;
 
-        if (kmsg_fd >= 0) {
-                close_nointr_nofail(kmsg_fd);
-                kmsg_fd = -1;
+        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;
+
+        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;
 
-        fprintf(stderr, "(%s:%u) %s", file, line, prefix);
-        vfprintf(stderr, format, ap);
-        fprintf(stderr, "%s\n", suffix);
+        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)
-
-void log_meta(
+static int log_dispatch(
+        int level,
+        const char*file,
+        int line,
+        const char *func,
+        const char *buffer) {
+
+        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. */
-
-        release_terminal();
-
-        if ((tty_fd = open_terminal("/dev/console", O_WRONLY|O_NOCTTY)) < 0) {
-                log_error("Failed to open /dev/console: %s", strerror(-tty_fd));
-                r = -tty_fd;
-                goto finish;
-        }
-
-        if ((null_fd = open("/dev/null", O_RDONLY)) < 0) {
+        if ((null_fd = open("/dev/null", O_RDWR)) < 0) {
                 log_error("Failed to open /dev/null: %m");
-                r = -errno;
-                goto finish;
+                return -errno;
         }
 
-        assert(tty_fd >= 3);
-        assert(null_fd >= 3);
+        if ((r = make_stdio(null_fd)) < 0)
+                log_warning("Failed to dup2() device: %s", strerror(-r));
 
-        if (do_reset)
-                if (reset_terminal(tty_fd) < 0)
-                        log_error("Failed to reset /dev/console: %m");
+        return r;
+}
 
-        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;
-        }
+static int console_setup(bool do_reset) {
+        int tty_fd, r;
 
-        r = 0;
+        /* If we are init, we connect stdin/stdout/stderr to /dev/null
+         * and make sure we don't have a controlling tty. */
 
-finish:
-        if (tty_fd >= 0)
-                close_nointr_nofail(tty_fd);
+        release_terminal();
+
+        if (!do_reset)
+                return 0;
 
-        if (null_fd >= 0)
-                close_nointr_nofail(null_fd);
+        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));
+                return -tty_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);
         }
 
+        /* 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_INIT && action == ACTION_RUN)
+        if (running_as != MANAGER_SESSION && 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);
+                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))      \