Merge pull request #1319 from brauner/2016-11-25/fix_logging_race

configure.ac

@@ -628,7 +628,7 @@ AC_CHECK_DECLS([PR_GET_NO_NEW_PRIVS], [], [], [#include <sys/prctl.h>])
 AC_CHECK_HEADERS([sys/signalfd.h pty.h ifaddrs.h sys/capability.h sys/personality.h utmpx.h sys/timerfd.h])
 
 # Check for some syscalls functions
-AC_CHECK_FUNCS([setns pivot_root sethostname unshare rand_r confstr faccessat])
+AC_CHECK_FUNCS([setns pivot_root sethostname unshare rand_r confstr faccessat gettid])
 
 # Check for some functions
 AC_CHECK_LIB(pthread, main)

src/lxc/log.c

@@ -45,6 +45,20 @@
 
 #define LXC_LOG_DATEFOMAT_SIZE  15
 
+#ifndef HAVE_GETTID
+static inline pid_t gettid(void)
+{
+#ifdef __NR_gettid
+	return (pid_t)syscall(SYS_gettid);
+#else
+	errno = ENOSYS;
+	return -1;
+#endif
+}
+#else
+extern pid_t gettid(void);
+#endif
+
 int lxc_log_fd = -1;
 static int syslog_enable = 0;
 int lxc_quiet_specified;
@@ -137,11 +151,11 @@ 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;
-	int ms;
+	int ms = 0;
 	int fd_to_use = -1;
 
 #ifndef NO_LXC_CONF
@@ -155,34 +169,56 @@ static int log_append_logfile(const struct lxc_log_appender *appender,
 	if (fd_to_use == -1)
 		return 0;
 
-	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 %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);
+	/* 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);
+	}
 
 	if (n < 0)
 		return n;
 
-	if (n < sizeof(buffer) - 1)
-		n += vsnprintf(buffer + n, sizeof(buffer) - n, event->fmt,
-			       *event->vap);
-	else {
-		WARN("truncated next event from %d to %zd bytes", n,
-		     sizeof(buffer));
+	if ((size_t)n < (sizeof(buffer) - 1))
+		n += vsnprintf(buffer + n, sizeof(buffer) - n, event->fmt, *event->vap);
+	else
 		n = sizeof(buffer) - 1;
-	}
 
 	buffer[n] = '\n';