test: Add support for matching diagnostic traces

include/vr.h

@@ -5,7 +5,13 @@
 
 #define VR_API __attribute__((visibility("default")))
 
-enum { VR_NOMEM = 1, VR_DUPLICATEID, VR_DUPLICATEADDRESS, VR_BADROLE };
+enum {
+    VR_NOMEM = 1,
+    VR_DUPLICATEID,
+    VR_DUPLICATEADDRESS,
+    VR_BADROLE,
+    VR_INVALID /* Invalid parameter */
+};
 
 /* Customizable tracer for debugging, logging and metrics purposes. */
 struct vr_tracer
@@ -129,7 +135,38 @@ struct vr
 VR_API int vr_init(struct vr *v, unsigned id);
 VR_API int vr_close(struct vr *v);
 
-VR_API int vr_step(void);
+enum vr_event_type {
+    VR_START = 1, /* Initial event starting the server. */
+    VR_RECEIVE    /* A message has been received from another server. */
+};
+
+/* Represents an external event that drives the VR engine forward (for example
+ * receiving a message). */
+struct vr_event
+{
+    unsigned long time;
+    enum vr_event_type type;
+    unsigned char unused;
+    unsigned short capacity;
+    unsigned char reserved[4];
+    union {
+        struct
+        {
+            unsigned long view;
+        } start;
+    };
+};
+
+/* Hold information about changes that user code must perform after a call to
+ * vr_step() returns (e.g. new messages that must be sent, etc.). */
+struct vr_update
+{
+    unsigned flags;
+};
+
+VR_API int vr_step(struct vr *v,
+                   const struct vr_event *event,
+                   struct vr_update *update);
 
 /**
  * User-definable dynamic memory allocation functions.

src/tracing.h

@@ -0,0 +1,58 @@
+/* Tracing functions and helpers. */
+
+#ifndef TRACING_H_
+#define TRACING_H_
+
+#include "../include/vr.h"
+
+#define LIKELY(x) __builtin_expect(!!(x), 1)
+
+/* Use TRACER to trace an event of type TYPE with the given INFO. */
+#define Trace(TRACER, TYPE, INFO)             \
+    do {                                      \
+        if (LIKELY(TRACER == NULL)) {         \
+            break;                            \
+        }                                     \
+        if (LIKELY(TRACER->version == 2)) {   \
+            TRACER->emit(TRACER, TYPE, INFO); \
+        }                                     \
+    } while (0)
+
+/* Emit a diagnostic message with the given tracer at level 3. */
+#define Infof(TRACER, ...) Logf(TRACER, 3, __VA_ARGS__)
+
+/* Emit diagnostic message with the given tracer at level 5. */
+#define Tracef(TRACER, ...) Logf(TRACER, 5, __VA_ARGS__)
+
+/* Use the tracer to log an event at the given level.
+ *
+ * The LEVEL parameter should be one of:
+ *
+ * - 1: error
+ * - 2: warning
+ * - 3: info
+ * - 4: debug
+ * - 5: trace
+ */
+#define Logf(TRACER, LEVEL, ...)                  \
+    do {                                          \
+        unsigned _type;                           \
+        struct vr_tracer_info _info;              \
+        static char _msg[1024];                   \
+                                                  \
+        if (LIKELY(TRACER == NULL)) {             \
+            break;                                \
+        }                                         \
+                                                  \
+        snprintf(_msg, sizeof _msg, __VA_ARGS__); \
+                                                  \
+        _type = VR_TRACER_DIAGNOSTIC;             \
+        _info.version = 1;                        \
+        _info.diagnostic.level = LEVEL;           \
+        _info.diagnostic.message = _msg;          \
+        _info.diagnostic.file = __FILE__;         \
+        _info.diagnostic.line = __LINE__;         \
+        TRACER->emit(TRACER, _type, &_info);      \
+    } while (0)
+
+#endif /* TRACING_H_ */

src/vr.c

@@ -1,7 +1,14 @@
 #include "../include/vr.h"
 
+#include <stdio.h>
+#include <string.h>
+
+#include "assert.h"
 #include "configuration.h"
 #include "heap.h"
+#include "tracing.h"
+
+#define infof(...) Infof(v->tracer, "> " __VA_ARGS__)
 
 int vr_init(struct vr *v, unsigned id)
 {
@@ -22,8 +29,60 @@ int vr_close(struct vr *v)
     return 0;
 }
 
-int vr_step(void)
+/* Emit a start message containing information about the current state. */
+static void stepStartEmitMessage(const struct vr *v)
+{
+    char msg[512] = {0};
+
+    if (v->view == 0) {
+        strcat(msg, "no state");
+        goto emit;
+    }
+
+    if (v->view > 0) {
+        char msg_term[64];
+        sprintf(msg_term, "view %lu", v->view);
+        strcat(msg, msg_term);
+    }
+
+emit:
+    infof("%s", msg);
+}
+
+/* Handle a VR_START event. */
+static int stepStart(struct vr *v, unsigned long view)
+{
+    v->view = view;
+    stepStartEmitMessage(v);
+    return 0;
+}
+
+int vr_step(struct vr *v,
+            const struct vr_event *event,
+            struct vr_update *update)
 {
+    int rv;
+
+    assert(event != NULL);
+    assert(update != NULL);
+
+    switch (event->type) {
+        case VR_START:
+            rv = stepStart(v, event->start.view);
+            break;
+        default:
+            rv = VR_INVALID;
+            break;
+    }
+
+    if (rv != 0) {
+        goto out;
+    }
+
+out:
+    if (rv != 0) {
+        return rv;
+    }
     return 0;
 }
 

test/integration/test_normal.c

@@ -25,6 +25,7 @@ SUITE(normal)
 TEST(normal, request, setUp, tearDown, 0, NULL)
 {
     struct fixture *f = data;
-    (void)f;
+    CLUSTER_START(1);
+    CLUSTER_TRACE("[   0] 1 > no state\n");
     return MUNIT_OK;
 }

test/integration/test_step.c

@@ -1,13 +1,36 @@
 #include "../../include/vr.h"
 #include "../lib/runner.h"
 
+static void *setUp(const MunitParameter params[], MUNIT_UNUSED void *user_data)
+{
+    struct vr *v = munit_malloc(sizeof *v);
+    int rv;
+
+    (void)params;
+    rv = vr_init(v, 1);
+    munit_assert_int(rv, ==, 0);
+
+    return v;
+}
+
+static void tearDown(void *data)
+{
+    struct vr *v = data;
+    vr_close(v);
+    free(v);
+}
+
 SUITE(step)
 
-/* Generation of the ID of the bootstrap dqlite node. */
-TEST(step, noop, NULL, NULL, 0, NULL)
+/* Passing an invalid event code results in an error. */
+TEST(step, invalid, setUp, tearDown, 0, NULL)
 {
+    struct vr *v = data;
+    struct vr_event event;
+    struct vr_update update;
     int rv;
-    rv = vr_step();
-    munit_assert_int(0, ==, rv);
+    event.type = 666;
+    rv = vr_step(v, &event, &update);
+    munit_assert_int(rv, ==, VR_INVALID);
     return MUNIT_OK;
 }

test/lib/cluster.c

@@ -74,6 +74,41 @@ static void serverClose(struct test_server *s)
     vr_close(&s->vr);
 }
 
+/* Fire the given event using raft_step() and process the resulting struct
+ * raft_update object. */
+static int serverStep(struct test_server *s, struct vr_event *event)
+{
+    struct vr *v = &s->vr;
+    struct vr_update update;
+    int rv;
+
+    munit_assert_true(s->running);
+
+    rv = vr_step(v, event, &update);
+    if (rv != 0) {
+        return rv;
+    }
+
+    return 0;
+}
+
+/* Start the server by passing to raft_step() a RAFT_START event with the
+ * current disk state. */
+static void serverStart(struct test_server *s)
+{
+    struct vr_event event;
+    int rv;
+
+    s->running = true;
+
+    event.time = s->cluster->time;
+    event.type = VR_START;
+    event.start.view = 0;
+
+    rv = serverStep(s, &event);
+    munit_assert_int(rv, ==, 0);
+}
+
 void test_cluster_setup(const MunitParameter params[], struct test_cluster *c)
 {
     unsigned i;
@@ -88,6 +123,13 @@ void test_cluster_setup(const MunitParameter params[], struct test_cluster *c)
     c->in_tear_down = false;
 }
 
+/* Return the server with the given @id. */
+static struct test_server *clusterGetServer(struct test_cluster *c, unsigned id)
+{
+    munit_assert_ulong(id, <=, TEST_CLUSTER_N_SERVERS);
+    return &c->servers[id - 1];
+}
+
 void test_cluster_tear_down(struct test_cluster *c)
 {
     unsigned i;
@@ -98,3 +140,72 @@ void test_cluster_tear_down(struct test_cluster *c)
         serverClose(&c->servers[i]);
     }
 }
+
+void test_cluster_start(struct test_cluster *c, unsigned id)
+{
+    struct test_server *server = clusterGetServer(c, id);
+    serverStart(server);
+}
+
+void test_cluster_step(struct test_cluster *c)
+{
+    (void)c;
+}
+
+bool test_cluster_trace(struct test_cluster *c, const char *expected)
+{
+    size_t n1;
+    size_t n2;
+    size_t i;
+    unsigned max_steps = 100;
+
+consume:
+    if (max_steps == 0) {
+        goto mismatch;
+    }
+    max_steps -= 1;
+
+    n1 = strlen(c->trace);
+    n2 = strlen(expected);
+
+    for (i = 0; i < n1 && i < n2; i++) {
+        if (c->trace[i] != expected[i]) {
+            break;
+        }
+    }
+
+    /* Check if we produced more output than the expected one. */
+    if (n1 > n2) {
+        goto mismatch;
+    }
+
+    /* If there's more expected output, check that so far we're good, then
+     * step and repeat. */
+    if (n1 < n2) {
+        if (i != n1) {
+            goto mismatch;
+        }
+        c->trace[0] = 0;
+        expected += i;
+        test_cluster_step(c);
+        goto consume;
+    }
+
+    munit_assert_ulong(n1, ==, n2);
+    if (i != n1) {
+        goto mismatch;
+    }
+
+    c->trace[0] = 0;
+
+    return true;
+
+mismatch:
+    fprintf(stderr, "==> Expected:\n");
+    fprintf(stderr, "%s\n", expected);
+
+    fprintf(stderr, "==> Actual:\n");
+    fprintf(stderr, "%s\n", c->trace);
+
+    return false;
+}