From b07511df5c6bdc1623add74d7ee14921e69043e5 Mon Sep 17 00:00:00 2001 From: Christian Brauner Date: Sun, 27 Nov 2016 23:41:06 +0100 Subject: [PATCH 1/5] 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 --- src/lxc/utils.h | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/lxc/utils.h b/src/lxc/utils.h index 0d63bb699..3d1ecee4a 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 c57dbb96588dbb8f79c40268a68fc38605e1f337 Mon Sep 17 00:00:00 2001 From: Christian Brauner Date: Sun, 27 Nov 2016 23:42:11 +0100 Subject: [PATCH 2/5] 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 --- src/lxc/log.c | 106 +++++++++++++++++++++----------------------------- src/lxc/log.h | 8 +++- 2 files changed, 51 insertions(+), 63 deletions(-) diff --git a/src/lxc/log.c b/src/lxc/log.c index e9f2d7dc6..413b381e2 100644 --- a/src/lxc/log.c +++ b/src/lxc/log.c @@ -43,21 +43,11 @@ #include "caps.h" #include "utils.h" -#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 +/* 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 ((__LXC_NUMSTRLEN) * 2) int lxc_log_fd = -1; static int syslog_enable = 0; @@ -148,15 +138,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[__LXC_NUMSTRLEN]; #ifndef NO_LXC_CONF if (!lxc_log_use_global_fd && current_config) @@ -169,48 +178,23 @@ 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, __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, + 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 3c0bbaacf..b9ee49756 100644 --- a/src/lxc/log.h +++ b/src/lxc/log.h @@ -34,6 +34,7 @@ #include #include #include +#include #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; \ From 65a9df895ec25017cd822cb14a4b3077bdfe2401 Mon Sep 17 00:00:00 2001 From: Christian Brauner Date: Mon, 28 Nov 2016 22:08:37 +0100 Subject: [PATCH 3/5] log: add lxc_unix_epoch_to_utc() Converts a unix time Epoch given by a struct timespec to a UTC string useable in our logging functions. Maybe expanded to allow for more generic formatting. Signed-off-by: Christian Brauner --- src/lxc/log.c | 41 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 41 insertions(+) diff --git a/src/lxc/log.c b/src/lxc/log.c index 413b381e2..4880f7bac 100644 --- a/src/lxc/log.c +++ b/src/lxc/log.c @@ -22,9 +22,12 @@ */ #define _GNU_SOURCE +#define __STDC_FORMAT_MACROS /* Required for PRIu64 to work. */ #include +#include #include #include +#include #include #include #include @@ -138,6 +141,44 @@ static int log_append_stderr(const struct lxc_log_appender *appender, } /*---------------------------------------------------------------------------*/ +int lxc_unix_epoch_to_utc(char *buf, size_t bufsize, const struct timespec *time) +{ + int64_t days, z, era, doe, yoe, year, doy, mp, day, month, d_in_s, + hours, h_in_s, minutes, seconds; + char nanosec[__LXC_NUMSTRLEN]; + int ret; + + /* See https://howardhinnant.github.io/date_algorithms.html for an + * explanation of the algorithm used here. + */ + days = time->tv_sec / 86400; + z = days + 719468; + era = (z >= 0 ? z : z - 146096) / 146097; + doe = (z - era * 146097); + yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365; + year = (yoe) + era * 400; + doy = doe - (365 * yoe + yoe / 4 - yoe / 100); + mp = (5 * doy + 2) / 153; + day = doy - (153 * mp + 2) / 5 + 1; + month = mp + (mp < 10 ? 3 : -9); + d_in_s = days * 86400; + hours = (time->tv_sec - d_in_s) / 3600; + h_in_s = hours * 3600; + minutes = (time->tv_sec - d_in_s - h_in_s) / 60; + seconds = (time->tv_sec - d_in_s - h_in_s - (minutes * 60)); + + ret = snprintf(nanosec, __LXC_NUMSTRLEN, "%ld", time->tv_nsec); + if (ret < 0 || ret >= __LXC_NUMSTRLEN) + return -1; + ret = snprintf(buf, bufsize, "%" PRId64 "%" PRId64 "%" PRId64 "%" PRId64 + "%" PRId64 "%" PRId64 ".%.3s", + year, month, day, hours, minutes, seconds, nanosec); + if (ret < 0 || (size_t)ret >= bufsize) + return -1; + + return 0; +} + /* 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 From e1378d359105a50923691dabd038fbfbf4c6b91b Mon Sep 17 00:00:00 2001 From: Christian Brauner Date: Mon, 28 Nov 2016 22:19:02 +0100 Subject: [PATCH 4/5] log: use lxc_unix_epoch_to_utc() This allows us to generate nice timestamps in a thread-safe manner without relying on locale touching functions from any libc. Signed-off-by: Christian Brauner --- src/lxc/log.c | 15 +++++---------- 1 file changed, 5 insertions(+), 10 deletions(-) diff --git a/src/lxc/log.c b/src/lxc/log.c index 4880f7bac..61f0cdc86 100644 --- a/src/lxc/log.c +++ b/src/lxc/log.c @@ -203,10 +203,9 @@ static int log_append_logfile(const struct lxc_log_appender *appender, struct lxc_log_event *event) { char buffer[LXC_LOG_BUFFER_SIZE]; - struct timespec zero_timespec = {0}; - int ret, n; + char date_time[LXC_LOG_TIME_SIZE]; + int n; int fd_to_use = -1; - char nanosec[__LXC_NUMSTRLEN]; #ifndef NO_LXC_CONF if (!lxc_log_use_global_fd && current_config) @@ -219,19 +218,15 @@ static int log_append_logfile(const struct lxc_log_appender *appender, if (fd_to_use == -1) return 0; - ret = snprintf(nanosec, __LXC_NUMSTRLEN, "%ld", event->timestamp.tv_nsec); - if (ret < 0 || ret >= LXC_LOG_TIME_SIZE) + if (lxc_unix_epoch_to_utc(date_time, LXC_LOG_TIME_SIZE, &event->timestamp) < 0) return 0; n = snprintf(buffer, sizeof(buffer), - "%15s%s%s [ %.0f.%.6s ] %-8s %s - %s:%s:%d - ", + "%15s%s%s %s %-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, + date_time, lxc_log_priority_to_string(event->priority), event->category, event->locinfo->file, event->locinfo->func, From d86c0d08c4f9a3e11fddf401a9d46372a8aa085d Mon Sep 17 00:00:00 2001 From: Christian Brauner Date: Tue, 29 Nov 2016 01:26:25 +0100 Subject: [PATCH 5/5] log: annotate lxc_unix_epoch_to_utc() Signed-off-by: Christian Brauner --- src/lxc/log.c | 64 +++++++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 59 insertions(+), 5 deletions(-) diff --git a/src/lxc/log.c b/src/lxc/log.c index 61f0cdc86..549a1602b 100644 --- a/src/lxc/log.c +++ b/src/lxc/log.c @@ -143,33 +143,87 @@ static int log_append_stderr(const struct lxc_log_appender *appender, /*---------------------------------------------------------------------------*/ int lxc_unix_epoch_to_utc(char *buf, size_t bufsize, const struct timespec *time) { - int64_t days, z, era, doe, yoe, year, doy, mp, day, month, d_in_s, - hours, h_in_s, minutes, seconds; + int64_t epoch_to_days, z, era, doe, yoe, year, doy, mp, day, month, + d_in_s, hours, h_in_s, minutes, seconds; char nanosec[__LXC_NUMSTRLEN]; int ret; /* See https://howardhinnant.github.io/date_algorithms.html for an * explanation of the algorithm used here. */ - days = time->tv_sec / 86400; - z = days + 719468; + + /* Convert Epoch in seconds to number of days. */ + epoch_to_days = time->tv_sec / 86400; + + /* Shift the Epoch from 1970-01-01 to 0000-03-01. */ + z = epoch_to_days + 719468; + + /* compute the era from the serial date by simply dividing by the number + * of days in an era (146097). + */ era = (z >= 0 ? z : z - 146096) / 146097; + + /* The day-of-era (doe) can then be found by subtracting the era number + * times the number of days per era, from the serial date. + */ doe = (z - era * 146097); + + /* From the day-of-era (doe), the year-of-era (yoe, range [0, 399]) can + * be computed. + */ yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365; + + /* Given year-of-era, and era, one can now compute the year. */ year = (yoe) + era * 400; + + /* Also the day-of-year, again with the year beginning on Mar. 1, can be + * computed from the day-of-era and year-of-era. + */ doy = doe - (365 * yoe + yoe / 4 - yoe / 100); + + /* Given day-of-year, find the month number. */ mp = (5 * doy + 2) / 153; + + /* From day-of-year and month-of-year we can now easily compute + * day-of-month. + */ day = doy - (153 * mp + 2) / 5 + 1; + + /* Transform the month number from the [0, 11] / [Mar, Feb] system to + * the civil system: [1, 12] to find the correct month. + */ month = mp + (mp < 10 ? 3 : -9); - d_in_s = days * 86400; + + /* Transform days in the epoch to seconds. */ + d_in_s = epoch_to_days * 86400; + + /* To find the current hour simply substract the Epoch_to_days from the + * total Epoch and divide by the number of seconds in an hour. + */ hours = (time->tv_sec - d_in_s) / 3600; + + /* Transform hours to seconds. */ h_in_s = hours * 3600; + + /* Calculate minutes by substracting the seconds for all days in the + * epoch and for all hours in the epoch and divide by the number of + * minutes in an hour. + */ minutes = (time->tv_sec - d_in_s - h_in_s) / 60; + + /* Calculate the seconds by substracting the seconds for all days in the + * epoch, hours in the epoch and minutes in the epoch. + */ seconds = (time->tv_sec - d_in_s - h_in_s - (minutes * 60)); + /* Make string from nanoseconds. */ ret = snprintf(nanosec, __LXC_NUMSTRLEN, "%ld", time->tv_nsec); if (ret < 0 || ret >= __LXC_NUMSTRLEN) return -1; + + /* Create final timestamp for the log and shorten nanoseconds to 3 + * digit precision. + */ ret = snprintf(buf, bufsize, "%" PRId64 "%" PRId64 "%" PRId64 "%" PRId64 "%" PRId64 "%" PRId64 ".%.3s", year, month, day, hours, minutes, seconds, nanosec);