Initial log format rework

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

.github/workflows/build-and-test.yml

@@ -16,8 +16,8 @@ jobs:
           - gcc
           - clang
         tracing:
-          - LIBRAFT_TRACE=1
-          - NOLIBRAFT_TRACE=1
+          - LIBRAFT_TRACE=8
+          - NOLIBRAFT_TRACE=8
     runs-on: ${{ matrix.os }}
 
     steps:

README.md

@@ -177,6 +177,8 @@ to detect corruptions that occurred during storage. It is therefore recommended
 lz4 compression by means of the ```--disable-lz4``` configure flag.
 
 Detailed tracing will be enabled when the environment variable `LIBRAFT_TRACE` is set upon startup.
+The value of it can be in `0..8` range and reperesents a tracing level, where
+`0` means "no traces" emitted, and `8` enables maximum verbosity.
 
 Notable users
 -------------

include/raft.h

@@ -458,13 +458,20 @@ struct raft_tracer
      */
     bool enabled;
 
+    /**
+     * Trace level.
+     */
+    unsigned level;
+
     /**
      * Emit the given trace message, possibly decorating it with the provided
      * metadata.
      */
     void (*emit)(struct raft_tracer *t,
                  const char *file,
-                 int line,
+                 unsigned int line,
+                 const char *func,
+                 unsigned int level,
                  const char *message);
 };
 

src/fixture.c

@@ -979,10 +979,14 @@ void ioClose(struct raft_io *raft_io)
 /* Custom emit tracer function which include the server ID. */
 static void emit(struct raft_tracer *t,
                  const char *file,
-                 int line,
+                 unsigned int line,
+                 const char *func,
+                 unsigned int level,
                  const char *message)
 {
     unsigned id = *(unsigned *)t->impl;
+    (void) func;
+    (void) level;
     fprintf(stderr, "%d: %30s:%*d - %s\n", id, file, 3, line, message);
 }
 

src/tracing.c

@@ -1,43 +1,97 @@
 #include <inttypes.h>
 #include <stdlib.h>
 #include <time.h>
+#include <unistd.h>    /* getpid */
+#include <string.h>    /* strstr, strlen */
 
 #include "tracing.h"
+#include "assert.h"    /* assert */
 
-static inline void noopTracerEmit(struct raft_tracer *t,
-                                  const char *file,
-                                  int line,
-                                  const char *message)
+static inline void noopTracerEmit(struct raft_tracer *t UNUSED,
+                                  const char *file UNUSED,
+                                  unsigned int line UNUSED,
+                                  const char *func UNUSED,
+                                  unsigned int level UNUSED,
+                                  const char *message UNUSED)
 {
-    (void)t;
-    (void)file;
-    (void)line;
-    (void)message;
 }
 struct raft_tracer NoopTracer = {.impl = NULL,
                                  .enabled = false,
                                  .emit = noopTracerEmit};
 
+static inline const char *tracer__short_file_name(const char *fname)
+{
+	static const char  top_src_dir[] = "raft/";
+	const char        *p;
+
+	p = strstr(fname, top_src_dir);
+	return p != NULL ? p + strlen(top_src_dir) : fname;
+}
+
+static inline const char *tracer__trace_level_name(unsigned int level)
+{
+
+	static const char *levels[] = {
+		"NONE", "ALWAYS", "FATAL", "ERROR", "WARN",
+		"NOTICE", "INFO", "DEBUG", "CALL"
+	};
+
+	return level < ARRAY_SIZE(levels) ? levels[level] : levels[0];
+}
+
+static pid_t tracer__pid_cached;
+
+static inline void tracer__emit(const char *file, unsigned int line,
+				const char *func, unsigned int level,
+				const char *message)
+{
+	struct timespec ts = {0};
+	struct tm       tm;
+	/* Use stack pointer instead of explicit thread id */
+	uint64_t        sp = (uint64_t) &sp;
+
+	clock_gettime(CLOCK_REALTIME, &ts);
+	gmtime_r(&ts.tv_sec, &tm);
+
+	fprintf(stderr,
+		"LIBRAFT[%5.5u] %04d-%02d-%02dT%02d:%02d:%02d.%09lu "
+		"%6.6x %-7s %-20s %s:%-3i %s\n",
+		tracer__pid_cached,
+
+		tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
+		tm.tm_hour, tm.tm_min, tm.tm_sec, ts.tv_nsec,
+
+		(unsigned)(sp & 0xffff),
+		tracer__trace_level_name(level),
+		func, tracer__short_file_name(file),
+	        line, message);
+}
+
 static inline void stderrTracerEmit(struct raft_tracer *t,
                                     const char *file,
-                                    int line,
+                                    unsigned int line,
+                                    const char *func,
+                                    unsigned int level,
                                     const char *message)
 {
-    (void)t;
-    struct timespec ts = {0};
-    /* ignore errors */
-    clock_gettime(CLOCK_REALTIME, &ts);
-    int64_t ns = ts.tv_sec * 1000000000 + ts.tv_nsec;
-    fprintf(stderr, "LIBRAFT   %" PRId64 " %s:%d %s\n", ns, file, line,
-            message);
+    assert(t->level < TRACE_NR);
+    if (level <= t->level)
+	    tracer__emit(file, line, func, level, message);
 }
 struct raft_tracer StderrTracer = {.impl = NULL,
                                    .enabled = false,
                                    .emit = stderrTracerEmit};
 
 void raft_tracer_maybe_enable(struct raft_tracer *tracer, bool enabled)
 {
-    if (getenv(LIBRAFT_TRACE) != NULL) {
+    const char *trace_level = getenv(LIBRAFT_TRACE);
+
+    if (trace_level != NULL) {
+        tracer__pid_cached = getpid();
         tracer->enabled = enabled;
+
+	tracer->level = (unsigned) atoi(trace_level);
+	tracer->level = tracer->level < TRACE_NR ? tracer->level : TRACE_NONE;
     }
+
 }

src/tracing.h

@@ -15,15 +15,24 @@ extern struct raft_tracer NoopTracer;
 extern struct raft_tracer StderrTracer;
 
 /* Emit a debug message with the given tracer. */
-#define Tracef(TRACER, ...)                                    \
-    do {                                                       \
-        if (UNLIKELY(TRACER != NULL && TRACER->emit != NULL && \
-                     TRACER->enabled)) {                       \
-            static char _msg[1024];                            \
-            snprintf(_msg, sizeof _msg, __VA_ARGS__);          \
-            TRACER->emit(TRACER, __FILE__, __LINE__, _msg);    \
-        }                                                      \
-    } while (0)
+#define Tracef0(TRACER, LEVEL, ...)				\
+        do {                                                    \
+        if (UNLIKELY(TRACER != NULL && TRACER->emit != NULL &&  \
+                     TRACER->enabled)) {                        \
+                char _msg[1024];                                \
+                snprintf(_msg, sizeof _msg, __VA_ARGS__);       \
+                TRACER->emit(TRACER, __FILE__, __LINE__,        \
+                             __func__, (LEVEL), _msg);		\
+        }                                                       \
+        } while (0)
+
+
+enum raft_trace_level {
+	TRACE_NONE, TRACE_ALWAYS, TRACE_FATAL, TRACE_ERROR, TRACE_WARN,
+	TRACE_NOTICE, TRACE_INFO, TRACE_DEBUG, TRACE_CALL, TRACE_NR
+};
+
+#define Tracef(TRACER, ...) Tracef0(TRACER, TRACE_INFO, __VA_ARGS__)
 
 /* Enable the tracer if the env variable is set or disable the tracer */
 void raft_tracer_maybe_enable(struct raft_tracer *tracer, bool enabled);

src/utils.h

@@ -10,4 +10,8 @@
 
 #define DBG() fprintf(stderr, "%s:%d\n", __func__, __LINE__)
 
+#define UNUSED __attribute__((unused))
+
+#define ARRAY_SIZE(a) ((sizeof (a)) / (sizeof (a)[0]))
+
 #endif /* RAFT_UTILS_H_ */

test/lib/tracer.c

@@ -3,10 +3,13 @@
 #include "munit.h"
 
 void TracerEmit(struct raft_tracer *t,
-                const char *file,
-                int line,
-                const char *message)
+		const char *file,
+		unsigned int line,
+		const char *func,
+		unsigned int level,
+		const char *message)
 {
     (void)t;
+    (void)level;
     fprintf(stderr, "%20s:%*d - %s\n", file, 3, line, message);
 }

test/lib/tracer.h

@@ -12,8 +12,10 @@
 #define TEAR_DOWN_TRACER
 
 void TracerEmit(struct raft_tracer *t,
-                const char *file,
-                int line,
-                const char *message);
+		const char *file,
+		unsigned int line,
+		const char *func,
+		unsigned int level,
+		const char *message);
 
 #endif /* TEST_TRACER_H */