From: Christian Brauner <christian.brauner@ubuntu.com>
Date: Fri, 25 Nov 2016 19:23:00 +0000 (+0100)
Subject: log: use N/A if getpid() != gettid() when threaded
X-Git-Tag: lxc-2.1.0~250^2
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=refs%2Fpull%2F1319%2Fhead;p=thirdparty%2Flxc.git

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 c2400197a..e9f2d7dc6 100644
--- 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;