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: 's avatarChristian Brauner <christian.brauner@ubuntu.com>
parent 0dcdbf8a
...@@ -151,7 +151,7 @@ static int log_append_stderr(const struct lxc_log_appender *appender, ...@@ -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, static int log_append_logfile(const struct lxc_log_appender *appender,
struct lxc_log_event *event) 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]; char buffer[LXC_LOG_BUFFER_SIZE];
struct tm newtime; struct tm newtime;
int n; int n;
...@@ -169,41 +169,53 @@ static int log_append_logfile(const struct lxc_log_appender *appender, ...@@ -169,41 +169,53 @@ 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;
/* localtime_r() can lead to deadlocks because it calls __tzset() and /* localtime_r() can lead to deadlocks when LXC is used multithreaded
* __tzconvert() internally. The deadlock stems from an interaction * because it calls __tzset() and __tzconvert() internally. The deadlock
* between these functions and the functions in monitor.c and * stems from an interaction between these functions and the functions
* commands.{c,h}. The latter functions will write to the log * in monitor.c and commands.{c,h}. Some of the latter functions will
* independent of the container thread that is currently running. Since * write to the log independent of the container thread that is
* the monitor fork()ed it seems to duplicate the mutex states of the * currently running. Since the monitor fork()ed it seems to duplicate
* time functions mentioned above. * the mutex states of the time functions mentioned above.
* As a short termm fix, I suggest to simply disable receiving the time * As a short term fix, I suggest to simply disable receiving the time
* when monitor.c or command.{c,h} functions are called. This should be * when these monitor.c or command.{c,h} functions are called. This
* ok, since the [lxc monitor] will only emit a few messages and * should be ok, since the [lxc monitor] will only emit a few messages
* thread-safety is currently more important than beautiful logs. The * and thread-safety is currently more important than beautiful logs.
* rest of the log stays the same as it was before. * The rest of the log stays the same as it was before.
*/ */
if (getpid() == gettid()) { if (getpid() == gettid()) {
if (!localtime_r(&event->timestamp.tv_sec, &newtime)) if (!localtime_r(&event->timestamp.tv_sec, &newtime))
return 0; return 0;
strftime(date, sizeof(date), "%Y%m%d%H%M%S", &newtime); strftime(date, sizeof(date), "%Y%m%d%H%M%S", &newtime);
ms = event->timestamp.tv_usec / 1000; 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) if (n < 0)
return n; 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); n += vsnprintf(buffer + n, sizeof(buffer) - n, event->fmt, *event->vap);
else else
n = sizeof(buffer) - 1; n = sizeof(buffer) - 1;
......
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