Commit 27e0a151 by Christian Brauner Committed by Stéphane Graber

log: fix race

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 causing the deadlock. 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. Here is an example output from logs where I printed the pid and tid of the process that is currently writing to the log: lxc 20161125170200.619 INFO lxc_start: 18695-18695: - start.c:lxc_check_inherited:243 - Closed inherited fd: 23. lxc 20161125170200.640 DEBUG lxc_start: 18677-18677: - start.c:__lxc_start:1334 - Not dropping CAP_SYS_BOOT or watching utmp. lxc 20161125170200.640 INFO lxc_cgroup: 18677-18677: - cgroups/cgroup.c:cgroup_init:68 - cgroup driver cgroupfs-ng initing for lxc-test-concurrent-0 ----------> lxc 20150427012246.000 INFO lxc_monitor: 13017-18622: - monitor.c:lxc_monitor_sock_name:178 - using monitor sock name lxc/ad055575fe28ddd5//var/lib/lxc lxc 20161125170200.662 DEBUG lxc_cgfsng: 18677-18677: - cgroups/cgfsng.c:filter_and_set_cpus:478 - No isolated cpus detected. lxc 20161125170200.662 DEBUG lxc_cgfsng: 18677-18677: - cgroups/cgfsng.c:handle_cpuset_hierarchy:648 - "cgroup.clone_children" was already set to "1". Signed-off-by: 's avatarChristian Brauner <christian.brauner@ubuntu.com>
parent 31db9984
...@@ -88,7 +88,7 @@ static int log_append_logfile(const struct lxc_log_appender *appender, ...@@ -88,7 +88,7 @@ static int log_append_logfile(const struct lxc_log_appender *appender,
char buffer[LXC_LOG_BUFFER_SIZE]; char buffer[LXC_LOG_BUFFER_SIZE];
struct tm newtime; struct tm newtime;
int n; int n;
int ms; int ms = 0;
int fd_to_use = -1; int fd_to_use = -1;
#ifndef NO_LXC_CONF #ifndef NO_LXC_CONF
...@@ -102,11 +102,25 @@ static int log_append_logfile(const struct lxc_log_appender *appender, ...@@ -102,11 +102,25 @@ static int log_append_logfile(const struct lxc_log_appender *appender,
if (fd_to_use == -1) if (fd_to_use == -1)
return 0; return 0;
if (!localtime_r(&event->timestamp.tv_sec, &newtime)) /* localtime_r() can lead to deadlocks because it calls __tzset() and
return 0; * __tzconvert() internally. The deadlock stems from an interaction
* between these functions and the functions in monitor.c and
strftime(date, sizeof(date), "%Y%m%d%H%M%S", &newtime); * commands.{c,h}. The latter functions will write to the log
ms = event->timestamp.tv_usec / 1000; * 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.
*/
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), n = snprintf(buffer, sizeof(buffer),
"%15s %10s.%03d %-8s %s - %s:%s:%d - ", "%15s %10s.%03d %-8s %s - %s:%s:%d - ",
log_prefix, log_prefix,
...@@ -121,13 +135,9 @@ static int log_append_logfile(const struct lxc_log_appender *appender, ...@@ -121,13 +135,9 @@ static int log_append_logfile(const struct lxc_log_appender *appender,
return n; return n;
if (n < sizeof(buffer) - 1) if (n < sizeof(buffer) - 1)
n += vsnprintf(buffer + n, sizeof(buffer) - n, event->fmt, n += vsnprintf(buffer + n, sizeof(buffer) - n, event->fmt, *event->vap);
*event->vap); else
else {
WARN("truncated next event from %d to %zd bytes", n,
sizeof(buffer));
n = sizeof(buffer) - 1; n = sizeof(buffer) - 1;
}
buffer[n] = '\n'; buffer[n] = '\n';
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment