[lxc-devel] [lxc/master] [RFC] log: drop all timezone conversion functions
brauner on Github
lxc-bot at linuxcontainers.org
Sun Nov 27 22:45:16 UTC 2016
A non-text attachment was scrubbed...
Name: not available
Type: text/x-mailbox
Size: 1727 bytes
Desc: not available
URL: <http://lists.linuxcontainers.org/pipermail/lxc-devel/attachments/20161127/26602011/attachment.bin>
-------------- next part --------------
From b07511df5c6bdc1623add74d7ee14921e69043e5 Mon Sep 17 00:00:00 2001
From: Christian Brauner <christian.brauner at ubuntu.com>
Date: Sun, 27 Nov 2016 23:41:06 +0100
Subject: [PATCH 1/2] utils: add macro __LXC_NUMSTRLEN
This macro can be used to set or allocate a string buffer that can hold any
64bit representable number.
Signed-off-by: Christian Brauner <christian.brauner at ubuntu.com>
---
src/lxc/utils.h | 4 ++++
1 file changed, 4 insertions(+)
diff --git a/src/lxc/utils.h b/src/lxc/utils.h
index 0d63bb6..3d1ecee 100644
--- a/src/lxc/utils.h
+++ b/src/lxc/utils.h
@@ -35,6 +35,10 @@
#include "initutils.h"
+/* Useful macros */
+/* Maximum number for 64 bit integer is a string with 21 digits: 2^64 - 1 = 21 */
+#define __LXC_NUMSTRLEN 21
+
/* returns 1 on success, 0 if there were any failures */
extern int lxc_rmdir_onedev(char *path, const char *exclude);
extern int get_u16(unsigned short *val, const char *arg, int base);
From 4ae219376b172c06a80cfb72e4decf1331295733 Mon Sep 17 00:00:00 2001
From: Christian Brauner <christian.brauner at ubuntu.com>
Date: Sun, 27 Nov 2016 23:42:11 +0100
Subject: [PATCH 2/2] log: drop all timezone conversion functions
Our log functions need to make extra sure that they are thread-safe. We had
some problems with that before. This especially involves time-conversion
functions. I don't want to find any localtime() or gmtime() functions or
relatives in here. Not even localtime_r() or gmtime_r() or relatives. They all
fiddle with global variables and locking in various libcs. They cause deadlocks
when liblxc is used multi-threaded and no matter how smart you think you are,
you __will__ cause trouble using them.
(As a short example how this can cause trouble: LXD uses forkstart to fork off
a new process that runs the container. At the same time the go runtime LXD
relies on does its own multi-threading thing which we can't control. The
fork()ing + threading then seems to mess with the locking states in these time
functions causing deadlocks.)
The current solution is to be good old unix people and use the Epoch as our
reference point and simply use the seconds and nanoseconds that have past since
then. This relies on clock_gettime() which is explicitly marked MT-Safe with no
restrictions! This way, anyone who is really strongly invested in getting the
actual time the log entry was created, can just convert it for themselves. Our
logging is mostly done for debugging purposes so don't try to make it pretty.
Pretty might cost you thread-safety.
Signed-off-by: Christian Brauner <christian.brauner at ubuntu.com>
---
src/lxc/log.c | 93 +++++++++++++++++++++++++++++------------------------------
src/lxc/log.h | 8 +++--
2 files changed, 52 insertions(+), 49 deletions(-)
diff --git a/src/lxc/log.c b/src/lxc/log.c
index e9f2d7d..f8bdf15 100644
--- a/src/lxc/log.c
+++ b/src/lxc/log.c
@@ -43,7 +43,11 @@
#include "caps.h"
#include "utils.h"
-#define LXC_LOG_DATEFOMAT_SIZE 15
+/* We're logging in seconds and nanoseconds. Assuming that the underlying
+ * datatype is currently at maximum a 64bit integer, we have a date string that
+ * is of maximum length (2^64 - 1) * 2 = (21 + 21) = 42.
+ */
+#define LXC_LOG_TIME_SIZE (21 + 21)
#ifndef HAVE_GETTID
static inline pid_t gettid(void)
@@ -148,15 +152,34 @@ static int log_append_stderr(const struct lxc_log_appender *appender,
}
/*---------------------------------------------------------------------------*/
+/* This function needs to make extra sure that it is thread-safe. We had some
+ * problems with that before. This especially involves time-conversion
+ * functions. I don't want to find any localtime() or gmtime() functions or
+ * relatives in here. Not even localtime_r() or gmtime_r() or relatives. They
+ * all fiddle with global variables and locking in various libcs. They cause
+ * deadlocks when liblxc is used multi-threaded and no matter how smart you
+ * think you are, you __will__ cause trouble using them.
+ * (As a short example how this can cause trouble: LXD uses forkstart to fork
+ * off a new process that runs the container. At the same time the go runtime
+ * LXD relies on does its own multi-threading thing which we can't controll. The
+ * fork()ing + threading then seems to mess with the locking states in these
+ * time functions causing deadlocks.)
+ * The current solution is to be good old unix people and use the Epoch as our
+ * reference point and simply use the seconds and nanoseconds that have past
+ * since then. This relies on clock_gettime() which is explicitly marked MT-Safe
+ * with no restrictions! This way, anyone who is really strongly invested in
+ * getting the actual time the log entry was created, can just convert it for
+ * themselves. Our logging is mostly done for debugging purposes so don't try
+ * to make it pretty. Pretty might cost you thread-safety.
+ */
static int log_append_logfile(const struct lxc_log_appender *appender,
struct lxc_log_event *event)
{
- char date[LXC_LOG_DATEFOMAT_SIZE] = "N/A";
char buffer[LXC_LOG_BUFFER_SIZE];
- struct tm newtime;
- int n;
- int ms = 0;
+ struct timespec zero_timespec = {0};
+ int ret, n;
int fd_to_use = -1;
+ char nanosec_since_epoch[__LXC_NUMSTRLEN];
#ifndef NO_LXC_CONF
if (!lxc_log_use_global_fd && current_config)
@@ -169,48 +192,24 @@ static int log_append_logfile(const struct lxc_log_appender *appender,
if (fd_to_use == -1)
return 0;
- /* 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);
- }
+ ret = snprintf(nanosec_since_epoch, __LXC_NUMSTRLEN, "%ld",
+ event->timestamp.tv_nsec);
+ if (ret < 0 || ret >= LXC_LOG_TIME_SIZE)
+ return 0;
+
+ n = snprintf(buffer, sizeof(buffer),
+ "%15s%s%s [ %.0f.%.6s ] %-8s %s - %s:%s:%d - ",
+ log_prefix,
+ log_vmname ? " " : "",
+ log_vmname ? log_vmname : "",
+ /* sec_since_epoch: Safely convert time_t type to
+ * double. */
+ difftime(event->timestamp.tv_sec, zero_timespec.tv_sec),
+ nanosec_since_epoch,
+ lxc_log_priority_to_string(event->priority),
+ event->category,
+ event->locinfo->file, event->locinfo->func,
+ event->locinfo->line);
if (n < 0)
return n;
diff --git a/src/lxc/log.h b/src/lxc/log.h
index 3c0bbaa..b9ee497 100644
--- a/src/lxc/log.h
+++ b/src/lxc/log.h
@@ -34,6 +34,7 @@
#include <strings.h>
#include <stdbool.h>
#include <syslog.h>
+#include <time.h>
#include "conf.h"
@@ -83,7 +84,7 @@ struct lxc_log_locinfo {
struct lxc_log_event {
const char* category;
int priority;
- struct timeval timestamp;
+ struct timespec timestamp;
struct lxc_log_locinfo *locinfo;
const char *fmt;
va_list *vap;
@@ -251,7 +252,10 @@ ATTR_UNUSED static inline void LXC_##PRIORITY(struct lxc_log_locinfo* locinfo, \
}; \
va_list va_ref; \
\
- gettimeofday(&evt.timestamp, NULL); \
+ /* clock_gettime() is explicitly marked as MT-Safe \
+ * without restrictions. So let's use it for our \
+ * logging stamps. */ \
+ clock_gettime(CLOCK_REALTIME, &evt.timestamp); \
\
va_start(va_ref, format); \
evt.vap = &va_ref; \
More information about the lxc-devel
mailing list