log: use N/A if getpid() != gettid() when threaded

Sample log output:

    lxc 20161125201943.819 INFO     lxc_start - start.c:lxc_check_inherited:243 - Closed inherited fd: 54.
--> lxc N/A                INFO     lxc_monitor - monitor.c:lxc_monitor_sock_name:178 - using monitor sock name lxc/ad055575fe28ddd5//var/lib/lxc
    lxc 20161125201943.958 DEBUG    lxc_commands - commands.c:lxc_cmd_handler:893 - peer has disconnected
--> lxc N/A                DEBUG    lxc_commands - commands.c:lxc_cmd_get_state:579 - 'lxc-test-concurrent-0' is in 'RUNNING' state
    lxc 20161125201943.960 DEBUG    lxc_commands - commands.c:lxc_cmd_handler:893 - peer has disconnected
    lxc 20161125201944.009 INFO     lxc_start - start.c:lxc_check_inherited:243 - Closed inherited fd: 3.

Signed-off-by: Christian Brauner <christian.brauner@ubuntu.com>

diff --git a/src/lxc/log.c b/src/lxc/log.c
index c2400197a00f1c008f4c1516c14093725b135ba8..e9f2d7dc663c05fc7eead42c7984cd0fdf5725a1 100644 (file)
--- a/src/lxc/log.c
+++ b/src/lxc/log.c
@@ -151,7 +151,7 @@ static int log_append_stderr(const struct lxc_log_appender *appender,
 static int log_append_logfile(const struct lxc_log_appender *appender,
                              struct lxc_log_event *event)
 {
-       char date[LXC_LOG_DATEFOMAT_SIZE] = "20150427012246";
+       char date[LXC_LOG_DATEFOMAT_SIZE] = "N/A";
        char buffer[LXC_LOG_BUFFER_SIZE];
        struct tm newtime;
        int n;
@@ -169,41 +169,53 @@ static int log_append_logfile(const struct lxc_log_appender *appender,
        if (fd_to_use == -1)
                return 0;
 
-       /* localtime_r() can lead to deadlocks because it calls __tzset() and
-        * __tzconvert() internally. The deadlock stems from an interaction
-        * between these functions and the functions in monitor.c and
-        * commands.{c,h}. The latter functions will write to the log
-        * independent of the container thread that is currently running. Since
-        * the monitor fork()ed it seems to duplicate the mutex states of the
-        * time functions mentioned above.
-        * As a short termm fix, I suggest to simply disable receiving the time
-        * when monitor.c or command.{c,h} functions are called. This should be
-        * ok, since the [lxc monitor] will only emit a few messages and
-        * thread-safety is currently more important than beautiful logs. The
-        * rest of the log stays the same as it was before.
+       /* localtime_r() can lead to deadlocks when LXC is used multithreaded
+        * because it calls __tzset() and __tzconvert() internally. The deadlock
+        * stems from an interaction between these functions and the functions
+        * in monitor.c and commands.{c,h}. Some of the latter functions will
+        * write to the log independent of the container thread that is
+        * currently running. Since the monitor fork()ed it seems to duplicate
+        * the mutex states of the time functions mentioned above.
+        * As a short term fix, I suggest to simply disable receiving the time
+        * when these monitor.c or command.{c,h} functions are called. This
+        * should be ok, since the [lxc monitor] will only emit a few messages
+        * and thread-safety is currently more important than beautiful logs.
+        * The rest of the log stays the same as it was before.
         */
        if (getpid() == gettid()) {
                if (!localtime_r(&event->timestamp.tv_sec, &newtime))
                        return 0;
                strftime(date, sizeof(date), "%Y%m%d%H%M%S", &newtime);
                ms = event->timestamp.tv_usec / 1000;
+               n = snprintf(buffer, sizeof(buffer),
+                               "%15s%s%s %14s.%03d %-8s %s - %s:%s:%d - ",
+                               log_prefix,
+                               log_vmname ? " " : "",
+                               log_vmname ? log_vmname : "",
+                               date,
+                               ms,
+                               lxc_log_priority_to_string(event->priority),
+                               event->category,
+                               event->locinfo->file, event->locinfo->func,
+                               event->locinfo->line);
+       } else {
+               n = snprintf(buffer, sizeof(buffer),
+                               "%15s%s%s %-14s %3s %-8s %s - %s:%s:%d - ",
+                               log_prefix,
+                               log_vmname ? " " : "",
+                               log_vmname ? log_vmname : "",
+                               date,
+                               "",
+                               lxc_log_priority_to_string(event->priority),
+                               event->category,
+                               event->locinfo->file, event->locinfo->func,
+                               event->locinfo->line);
        }
-       n = snprintf(buffer, sizeof(buffer),
-                    "%15s%s%s %10s.%03d %-8s %s - %s:%s:%d - ",
-                    log_prefix,
-                    log_vmname ? " " : "",
-                    log_vmname ? log_vmname : "",
-                    date,
-                    ms,
-                    lxc_log_priority_to_string(event->priority),
-                    event->category,
-                    event->locinfo->file, event->locinfo->func,
-                    event->locinfo->line);
 
        if (n < 0)
                return n;
 
-       if (n < sizeof(buffer) - 1)
+       if ((size_t)n < (sizeof(buffer) - 1))
                n += vsnprintf(buffer + n, sizeof(buffer) - n, event->fmt, *event->vap);
        else
                n = sizeof(buffer) - 1;