diff --git a/configure.ac b/configure.ac index cd424c450..2b284cdea 100644 --- a/configure.ac +++ b/configure.ac @@ -628,7 +628,7 @@ AC_CHECK_DECLS([PR_GET_NO_NEW_PRIVS], [], [], [#include ]) 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) diff --git a/src/lxc/log.c b/src/lxc/log.c index a08cc2637..e9f2d7dc6 100644 --- a/src/lxc/log.c +++ b/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';