Initial log format rework

 - Removed static qualifier from tracef() to fix potential
   multithreading bug;
 - Added log levels.

Signed-off-by: Anatoliy Bilenko <[email protected]>

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).

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

src/tracing.c

@@ -1,14 +1,98 @@
 #include "tracing.h"
-
+#include <stdio.h> /* stderr */
 #include <stdlib.h>
+#include <string.h>      /* strstr, strlen */
+#include <sys/syscall.h> /* syscall */
+#include <unistd.h>      /* 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);
+}

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);