From 4c7743bc4c11d66c08feac3afcfb66a7bd773b25 Mon Sep 17 00:00:00 2001 From: Anatoliy Bilenko Date: Tue, 28 Nov 2023 10:58:16 +0000 Subject: [PATCH] Initial log format rework - Removed static qualifier from tracef() to fix potential multithreading bug; - Added log levels. Signed-off-by: Anatoliy Bilenko --- README.md | 4 ++- src/lib/byte.h | 2 ++ src/tracing.c | 88 ++++++++++++++++++++++++++++++++++++++++++++++++-- src/tracing.h | 48 +++++++++++++++++++-------- 4 files changed, 126 insertions(+), 16 deletions(-) diff --git a/README.md b/README.md index 3e4e6bb93..52e68abcb 100644 --- a/README.md +++ b/README.md @@ -113,4 +113,6 @@ Usage Notes ----------- Detailed tracing will be enabled when the environment variable `LIBDQLITE_TRACE` is set before startup. - +The value of it can be in `[0..5]` range and reperesents a tracing level, where +`0` means "no traces" emitted, `5` enables minimum (FATAL records only), and `1` +enables maximum verbosity (all: DEBUG, INFO, WARN, ERROR, FATAL records). diff --git a/src/lib/byte.h b/src/lib/byte.h index cb6c5cd6c..fea3d2d7f 100644 --- a/src/lib/byte.h +++ b/src/lib/byte.h @@ -136,6 +136,8 @@ DQLITE_INLINE size_t BytePad64(size_t size) return size; } +#define ARRAY_SIZE(a) ((sizeof(a)) / (sizeof(a)[0])) + #if defined(__GNUC__) && __GNUC__ < 10 #pragma GCC diagnostic pop #endif diff --git a/src/tracing.c b/src/tracing.c index bb32e2f13..96c148e28 100644 --- a/src/tracing.c +++ b/src/tracing.c @@ -1,14 +1,98 @@ #include "tracing.h" - +#include /* stderr */ #include +#include /* strstr, strlen */ +#include /* syscall */ +#include /* syscall, getpid */ +#include "assert.h" /* assert */ +#include "lib/byte.h" /* ARRAY_SIZE */ #define LIBDQLITE_TRACE "LIBDQLITE_TRACE" bool _dqliteTracingEnabled = false; +static unsigned tracer__level; +static pid_t tracerPidCached; void dqliteTracingMaybeEnable(bool enable) { - if (getenv(LIBDQLITE_TRACE) != NULL) { + const char *trace_level = getenv(LIBDQLITE_TRACE); + + if (trace_level != NULL) { + tracerPidCached = getpid(); _dqliteTracingEnabled = enable; + + tracer__level = (unsigned)atoi(trace_level); + tracer__level = + tracer__level < TRACE_NR ? tracer__level : TRACE_NONE; } } + +static inline const char *tracerShortFileName(const char *fname) +{ + static const char top_src_dir[] = "dqlite/"; + const char *p; + + p = strstr(fname, top_src_dir); + return p != NULL ? p + strlen(top_src_dir) : fname; +} + +static inline const char *tracerTraceLevelName(unsigned int level) +{ + static const char *levels[] = { + "NONE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL", + }; + + return level < ARRAY_SIZE(levels) ? levels[level] : levels[0]; +} + +static pid_t tracerPidCached; + +/* NOTE: on i386 and other platforms there're no specifically imported gettid() + functions in unistd.h +*/ +static inline pid_t gettidImpl(void) +{ + return (pid_t)syscall(SYS_gettid); +} + +static inline void tracerEmit(const char *file, + unsigned int line, + const char *func, + unsigned int level, + const char *message) +{ + struct timespec ts = {0}; + struct tm tm; + pid_t tid = gettidImpl(); + + clock_gettime(CLOCK_REALTIME, &ts); + gmtime_r(&ts.tv_sec, &tm); + + /* + Example: + LIBDQLITE[182942] 2023-11-27T14:46:24.912050507 001132 INFO + uvClientSend src/uv_send.c:218 connection available... + */ + fprintf(stderr, + "LIBDQLITE[%6.6u] %04d-%02d-%02dT%02d:%02d:%02d.%09lu " + "%6.6u %-7s %-20s %s:%-3i %s\n", + tracerPidCached, + + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, + tm.tm_min, tm.tm_sec, ts.tv_nsec, + + (unsigned)tid, tracerTraceLevelName(level), func, + tracerShortFileName(file), line, message); +} + +void stderrTracerEmit(const char *file, + unsigned int line, + const char *func, + unsigned int level, + const char *message) +{ + assert(tracer__level < TRACE_NR); + + if (level >= tracer__level) + tracerEmit(file, line, func, level, message); +} diff --git a/src/tracing.h b/src/tracing.h index 35e2f9c42..31bc0e7a3 100644 --- a/src/tracing.h +++ b/src/tracing.h @@ -15,21 +15,43 @@ /* This global variable is only written once at startup and is only read * from there on. Users should not manipulate the value of this variable. */ DQLITE_VISIBLE_TO_TESTS extern bool _dqliteTracingEnabled; - -#define tracef(...) \ - do { \ - if (UNLIKELY(_dqliteTracingEnabled)) { \ - static char _msg[1024]; \ - snprintf(_msg, sizeof(_msg), __VA_ARGS__); \ - struct timespec ts = {0}; \ - /* Ignore errors */ \ - clock_gettime(CLOCK_REALTIME, &ts); \ - int64_t ns = ts.tv_sec * 1000000000 + ts.tv_nsec; \ - fprintf(stderr, "LIBDQLITE %" PRId64 " %s:%d %s\n", \ - ns, __func__, __LINE__, _msg); \ - } \ +DQLITE_VISIBLE_TO_TESTS void stderrTracerEmit(const char *file, + unsigned int line, + const char *func, + unsigned int level, + const char *message); + +#define tracef0(LEVEL, ...) \ + do { \ + if (UNLIKELY(_dqliteTracingEnabled)) { \ + char _msg[1024]; \ + snprintf(_msg, sizeof _msg, __VA_ARGS__); \ + stderrTracerEmit(__FILE__, __LINE__, __func__, \ + (LEVEL), _msg); \ + } \ } while (0) +enum dqlite_trace_level { + /** Represents an invalid trace level */ + TRACE_NONE, + /** Lower-level information to debug and analyse incorrect behavior */ + TRACE_DEBUG, + /** Information about current system's state */ + TRACE_INFO, + /** + * Condition which requires a special handling, something which doesn't + * happen normally + */ + TRACE_WARN, + /** Resource unavailable, no connectivity, invalid value, etc. */ + TRACE_ERROR, + /** System is not able to continue performing its basic function */ + TRACE_FATAL, + TRACE_NR, +}; + +#define tracef(...) tracef0(TRACE_DEBUG, __VA_ARGS__) + /* Enable tracing if the appropriate env variable is set, or disable tracing. */ DQLITE_VISIBLE_TO_TESTS void dqliteTracingMaybeEnable(bool enabled);