Merge pull request #7990 from poettering/log-deadlock

fix for logging deadlock

src/basic/log.c

@@ -77,6 +77,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;
+static bool prohibit_ipc = false;
 
 /* Akin to glibc's __abort_msg; which is private and we hence cannot
  * use here. */
@@ -250,11 +251,12 @@ int log_open(void) {
                 return 0;
         }
 
-        if (!IN_SET(log_target, LOG_TARGET_AUTO, LOG_TARGET_SAFE) ||
+        if (log_target != LOG_TARGET_AUTO ||
             getpid_cached() == 1 ||
             isatty(STDERR_FILENO) <= 0) {
 
-                if (IN_SET(log_target, LOG_TARGET_AUTO,
+                if (!prohibit_ipc &&
+                    IN_SET(log_target, LOG_TARGET_AUTO,
                                        LOG_TARGET_JOURNAL_OR_KMSG,
                                        LOG_TARGET_JOURNAL)) {
                         r = log_open_journal();
@@ -265,7 +267,8 @@ int log_open(void) {
                         }
                 }
 
-                if (IN_SET(log_target, LOG_TARGET_SYSLOG_OR_KMSG,
+                if (!prohibit_ipc &&
+                    IN_SET(log_target, LOG_TARGET_SYSLOG_OR_KMSG,
                                        LOG_TARGET_SYSLOG)) {
                         r = log_open_syslog();
                         if (r >= 0) {
@@ -276,7 +279,6 @@ int log_open(void) {
                 }
 
                 if (IN_SET(log_target, LOG_TARGET_AUTO,
-                                       LOG_TARGET_SAFE,
                                        LOG_TARGET_JOURNAL_OR_KMSG,
                                        LOG_TARGET_SYSLOG_OR_KMSG,
                                        LOG_TARGET_KMSG)) {
@@ -628,7 +630,6 @@ int log_dispatch_internal(
 
                 if (k <= 0 &&
                     IN_SET(log_target, LOG_TARGET_AUTO,
-                                       LOG_TARGET_SAFE,
                                        LOG_TARGET_SYSLOG_OR_KMSG,
                                        LOG_TARGET_JOURNAL_OR_KMSG,
                                        LOG_TARGET_KMSG)) {
@@ -1220,8 +1221,7 @@ static const char *const log_target_table[_LOG_TARGET_MAX] = {
         [LOG_TARGET_SYSLOG] = "syslog",
         [LOG_TARGET_SYSLOG_OR_KMSG] = "syslog-or-kmsg",
         [LOG_TARGET_AUTO] = "auto",
-        [LOG_TARGET_SAFE] = "safe",
-        [LOG_TARGET_NULL] = "null"
+        [LOG_TARGET_NULL] = "null",
 };
 
 DEFINE_STRING_TABLE_LOOKUP(log_target, LogTarget);
@@ -1314,6 +1314,14 @@ int log_syntax_invalid_utf8_internal(
 
 void log_set_upgrade_syslog_to_journal(bool b) {
         upgrade_syslog_to_journal = b;
+
+        /* Make the change effective immediately */
+        if (b) {
+                if (log_target == LOG_TARGET_SYSLOG)
+                        log_target = LOG_TARGET_JOURNAL;
+                else if (log_target == LOG_TARGET_SYSLOG_OR_KMSG)
+                        log_target = LOG_TARGET_JOURNAL_OR_KMSG;
+        }
 }
 
 void log_set_always_reopen_console(bool b) {
@@ -1324,6 +1332,10 @@ void log_set_open_when_needed(bool b) {
         open_when_needed = b;
 }
 
+void log_set_prohibit_ipc(bool b) {
+        prohibit_ipc = b;
+}
+
 int log_emergency_level(void) {
         /* Returns the log level to use for log_emergency() logging. We use LOG_EMERG only when we are PID 1, as only
          * then the system of the whole system is obviously affected. */

src/basic/log.h

@@ -50,7 +50,6 @@ typedef enum LogTarget{
         LOG_TARGET_SYSLOG,
         LOG_TARGET_SYSLOG_OR_KMSG,
         LOG_TARGET_AUTO, /* console if stderr is tty, JOURNAL_OR_KMSG otherwise */
-        LOG_TARGET_SAFE, /* console if stderr is tty, KMSG otherwise */
         LOG_TARGET_NULL,
         _LOG_TARGET_MAX,
         _LOG_TARGET_INVALID = -1
@@ -302,10 +301,20 @@ LogTarget log_target_from_string(const char *s) _pure_;
 
 void log_received_signal(int level, const struct signalfd_siginfo *si);
 
+/* If turned on, any requests for a log target involving "syslog" will be implicitly upgraded to the equivalent journal target */
 void log_set_upgrade_syslog_to_journal(bool b);
+
+/* If turned on, and log_open() is called, we'll not use STDERR_FILENO for logging ever, but rather open /dev/console */
 void log_set_always_reopen_console(bool b);
+
+/* If turned on, we'll open the log stream implicitly if needed on each individual log call. This is normally not
+ * desired as we want to reuse our logging streams. It is useful however  */
 void log_set_open_when_needed(bool b);
 
+/* If turned on, then we'll never use IPC-based logging, i.e. never log to syslog or the journal. We'll only log to
+ * stderr, the console or kmsg */
+void log_set_prohibit_ipc(bool b);
+
 int log_syntax_internal(
                 const char *unit,
                 int level,

src/core/main.c

@@ -2328,12 +2328,17 @@ int main(int argc, char *argv[]) {
         saved_argv = argv;
         saved_argc = argc;
 
+        /* Make sure that if the user says "syslog" we actually log to the journal. */
         log_set_upgrade_syslog_to_journal(true);
 
         if (getpid_cached() == 1) {
                 /* Disable the umask logic */
                 umask(0);
 
+                /* Make sure that at least initially we do not ever log to journald/syslogd, because it might not be activated
+                 * yet (even though the log socket for it exists). */
+                log_set_prohibit_ipc(true);
+
                 /* Always reopen /dev/console when running as PID 1 or one of its pre-execve() children. This is
                  * important so that we never end up logging to any foreign stderr, for example if we have to log in a
                  * child process right before execve()'ing the actual binary, at a point in time where socket

src/core/manager.c

@@ -3132,6 +3132,9 @@ int manager_reload(Manager *m) {
         manager_vacuum_uid_refs(m);
         manager_vacuum_gid_refs(m);
 
+        /* It might be safe to log to the journal now. */
+        manager_recheck_journal(m);
+
         /* Sync current state of bus names with our set of listening units */
         if (m->api_bus)
                 manager_sync_bus_names(m, m->api_bus);
@@ -3482,29 +3485,52 @@ int manager_set_default_rlimits(Manager *m, struct rlimit **default_rlimit) {
         return 0;
 }
 
-void manager_recheck_journal(Manager *m) {
+static bool manager_journal_is_running(Manager *m) {
         Unit *u;
 
         assert(m);
 
+        /* If we are the user manager we can safely assume that the journal is up */
         if (!MANAGER_IS_SYSTEM(m))
-                return;
+                return true;
 
+        /* Check that the socket is not only up, but in RUNNING state */
         u = manager_get_unit(m, SPECIAL_JOURNALD_SOCKET);
-        if (u && SOCKET(u)->state != SOCKET_RUNNING) {
-                log_close_journal();
-                return;
-        }
+        if (!u)
+                return false;
+        if (SOCKET(u)->state != SOCKET_RUNNING)
+                return false;
 
+        /* Similar, check if the daemon itself is fully up, too */
         u = manager_get_unit(m, SPECIAL_JOURNALD_SERVICE);
-        if (u && SERVICE(u)->state != SERVICE_RUNNING) {
-                log_close_journal();
-                return;
-        }
+        if (!u)
+                return false;
+        if (SERVICE(u)->state != SERVICE_RUNNING)
+                return false;
 
-        /* Hmm, OK, so the socket is fully up and the service is up
-         * too, then let's make use of the thing. */
-        log_open();
+        return true;
+}
+
+void manager_recheck_journal(Manager *m) {
+
+        assert(m);
+
+        /* Don't bother with this unless we are in the special situation of being PID 1 */
+        if (getpid_cached() != 1)
+                return;
+
+        if (manager_journal_is_running(m)) {
+
+                /* The journal is fully and entirely up? If so, let's permit logging to it, if that's configured. */
+                log_set_prohibit_ipc(false);
+                log_open();
+        } else {
+
+                /* If the journal is down, don't ever log to it, otherwise we might end up deadlocking ourselves as we
+                 * might trigger an activation ourselves we can't fulfill */
+                log_set_prohibit_ipc(true);
+                log_close_journal();
+        }
 }
 
 void manager_set_show_status(Manager *m, ShowStatus mode) {

src/cryptsetup/cryptsetup-generator.c

@@ -472,7 +472,8 @@ int main(int argc, char *argv[]) {
         if (argc > 1)
                 arg_dest = argv[1];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();
 

src/debug-generator/debug-generator.c

@@ -165,7 +165,8 @@ int main(int argc, char *argv[]) {
         if (argc > 1)
                 arg_dest = argv[2];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();
 

src/fstab-generator/fstab-generator.c

@@ -891,7 +891,8 @@ int main(int argc, char *argv[]) {
         if (argc > 3)
                 arg_dest_late = argv[3];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();
 

src/getty-generator/getty-generator.c

@@ -138,7 +138,8 @@ int main(int argc, char *argv[]) {
         if (argc > 1)
                 arg_dest = argv[1];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();
 

src/gpt-auto-generator/gpt-auto-generator.c

@@ -713,7 +713,8 @@ int main(int argc, char *argv[]) {
         if (argc > 1)
                 arg_dest = argv[3];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();
 

src/hibernate-resume/hibernate-resume-generator.c

@@ -86,7 +86,8 @@ int main(int argc, char *argv[]) {
         if (argc > 1)
                 arg_dest = argv[1];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();
 

src/journal/journald.c

@@ -40,7 +40,8 @@ int main(int argc, char *argv[]) {
                 return EXIT_FAILURE;
         }
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_set_facility(LOG_SYSLOG);
         log_parse_environment();
         log_open();

src/rc-local-generator/rc-local-generator.c

@@ -64,7 +64,8 @@ int main(int argc, char *argv[]) {
         if (argc > 1)
                 arg_dest = argv[1];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();
 

src/system-update-generator/system-update-generator.c

@@ -79,7 +79,8 @@ int main(int argc, char *argv[]) {
         if (argc > 1)
                 arg_dest = argv[2];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();
 

src/sysv-generator/sysv-generator.c

@@ -950,7 +950,8 @@ int main(int argc, char *argv[]) {
         if (argc > 1)
                 arg_dest = argv[3];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();
 

src/veritysetup/veritysetup-generator.c

@@ -228,7 +228,8 @@ int main(int argc, char *argv[]) {
         if (argc > 1)
                 arg_dest = argv[1];
 
-        log_set_target(LOG_TARGET_SAFE);
+        log_set_prohibit_ipc(true);
+        log_set_target(LOG_TARGET_AUTO);
         log_parse_environment();
         log_open();