Merge pull request #225 from MathieuBordere/debugtrace

Debugtrace
canonical · Aug 11, 2021 · b8af7c5 · b8af7c5
2 parents f1825a3 + 0f66f91
commit b8af7c5
Show file tree

Hide file tree

Showing 33 changed files with 153 additions and 149 deletions.
diff --git a/README.md b/README.md
@@ -157,6 +157,8 @@ compressed snapshots offer additional data integrity checks in the form of a
 to detect corruptions that occurred during storage. It is therefore recommended to not disable
 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.
+
 Notable users
 -------------
 

diff --git a/include/raft.h b/include/raft.h
@@ -416,6 +416,11 @@ struct raft_tracer
      */
     void *impl;
 
+    /**
+     * Whether this tracer should emit messages.
+     */
+    bool enabled;
+
     /**
      * Emit the given trace message, possibly decorating it with the provided
      * metadata.

diff --git a/src/client.c b/src/client.c
@@ -10,12 +10,7 @@
 #include "request.h"
 #include "tracing.h"
 
-/* Set to 1 to enable tracing. */
-#if 0
 #define tracef(...) Tracef(r->tracer, __VA_ARGS__)
-#else
-#define tracef(...)
-#endif
 
 int raft_apply(struct raft *r,
                struct raft_apply *req,
@@ -33,6 +28,7 @@ int raft_apply(struct raft *r,
     if (r->state != RAFT_LEADER || r->transfer != NULL) {
         rv = RAFT_NOTLEADER;
         ErrMsgFromCode(r->errmsg, rv);
+        tracef("raft_apply not leader");
         goto err;
     }
 
@@ -182,7 +178,7 @@ int raft_add(struct raft *r,
         return rv;
     }
 
-    tracef("add server: id %d, address %s", id, address);
+    tracef("add server: id %llu, address %s", id, address);
 
     /* Make a copy of the current configuration, and add the new server to
      * it. */
@@ -226,6 +222,7 @@ int raft_assign(struct raft *r,
     raft_index last_index;
     int rv;
 
+    tracef("raft_assign to id:%llu the role:%d", id, role);
     if (role != RAFT_STANDBY && role != RAFT_VOTER && role != RAFT_SPARE) {
         rv = RAFT_BADROLE;
         ErrMsgFromCode(r->errmsg, rv);
@@ -287,6 +284,7 @@ int raft_assign(struct raft *r,
 
         rv = clientChangeConfiguration(r, req, &r->configuration);
         if (rv != 0) {
+            tracef("clientChangeConfiguration failed %d", rv);
             r->configuration.servers[server_index].role = old_role;
             return rv;
         }
@@ -305,7 +303,7 @@ int raft_assign(struct raft *r,
     rv = replicationProgress(r, server_index);
     if (rv != 0 && rv != RAFT_NOCONNECTION) {
         /* This error is not fatal. */
-        tracef("failed to send append entries to server %u: %s (%d)",
+        tracef("failed to send append entries to server %llu: %s (%d)",
                server->id, raft_strerror(rv), rv);
     }
 
@@ -336,7 +334,7 @@ int raft_remove(struct raft *r,
         goto err;
     }
 
-    tracef("remove server: id %d", id);
+    tracef("remove server: id %llu", id);
 
     /* Make a copy of the current configuration, and remove the given server
      * from it. */
@@ -403,7 +401,9 @@ int raft_transfer(struct raft *r,
     unsigned i;
     int rv;
 
+    tracef("transfer to %llu", id);
     if (r->state != RAFT_LEADER || r->transfer != NULL) {
+        tracef("transfer error - state:%d", r->state);
         rv = RAFT_NOTLEADER;
         ErrMsgFromCode(r->errmsg, rv);
         goto err;

diff --git a/src/configuration.c b/src/configuration.c
@@ -2,10 +2,12 @@
 
 #include "assert.h"
 #include "byte.h"
+#include "tracing.h"
 
 /* Current encoding format version. */
 #define ENCODING_FORMAT 1
 
+
 void configurationInit(struct raft_configuration *c)
 {
     c->servers = NULL;
@@ -329,3 +331,22 @@ int configurationDecode(const struct raft_buffer *buf,
 
     return 0;
 }
+
+#define tracef(...) Tracef(r->tracer, __VA_ARGS__)
+void configurationTrace(const struct raft *r, struct raft_configuration *c, const char *msg)
+{
+    if (!r->tracer->enabled || r == NULL || c == NULL) {
+        return;
+    }
+
+    tracef("%s", msg);
+    tracef("=== CONFIG START ===");
+    unsigned i;
+    struct raft_server *s;
+    for (i = 0; i < c->n; i++) {
+        s = &c->servers[i];
+        tracef("id:%llu address:%s role:%d", s->id, s->address, s->role);
+    }
+    tracef("=== CONFIG END ===");
+}
+#undef tracef
diff --git a/src/configuration.h b/src/configuration.h
@@ -61,4 +61,6 @@ int configurationEncode(const struct raft_configuration *c,
 int configurationDecode(const struct raft_buffer *buf,
                         struct raft_configuration *c);
 
+/* Output the configuration to the raft tracer */
+void configurationTrace(const struct raft *r, struct raft_configuration *c, const char *msg);
 #endif /* CONFIGURATION_H_ */
diff --git a/src/convert.c b/src/convert.c
@@ -8,13 +8,9 @@
 #include "progress.h"
 #include "queue.h"
 #include "request.h"
+#include "tracing.h"
 
-/* Set to 1 to enable tracing. */
-#if 0
 #define tracef(...) Tracef(r->tracer, __VA_ARGS__)
-#else
-#define tracef(...)
-#endif
 
 /* Convenience for setting a new state value and asserting that the transition
  * is valid. */
@@ -23,6 +19,7 @@ static void convertSetState(struct raft *r, unsigned short new_state)
     /* Check that the transition is legal, see Figure 3.3. Note that with
      * respect to the paper we have an additional "unavailable" state, which is
      * the initial or final state. */
+    tracef("old_state:%u new_state:%u", r->state, new_state);
     assert((r->state == RAFT_UNAVAILABLE && new_state == RAFT_FOLLOWER) ||
            (r->state == RAFT_FOLLOWER && new_state == RAFT_CANDIDATE) ||
            (r->state == RAFT_CANDIDATE && new_state == RAFT_FOLLOWER) ||
@@ -37,6 +34,7 @@ static void convertSetState(struct raft *r, unsigned short new_state)
 /* Clear follower state. */
 static void convertClearFollower(struct raft *r)
 {
+    tracef("clear follower state");
     r->follower_state.current_leader.id = 0;
     if (r->follower_state.current_leader.address != NULL) {
         raft_free(r->follower_state.current_leader.address);
@@ -47,6 +45,7 @@ static void convertClearFollower(struct raft *r)
 /* Clear candidate state. */
 static void convertClearCandidate(struct raft *r)
 {
+    tracef("clear candidate state");
     if (r->candidate_state.votes != NULL) {
         raft_free(r->candidate_state.votes);
         r->candidate_state.votes = NULL;
@@ -77,6 +76,7 @@ static void convertFailChange(struct raft_change *req)
 /* Clear leader state. */
 static void convertClearLeader(struct raft *r)
 {
+    tracef("clear leader state");
     if (r->leader_state.progress != NULL) {
         raft_free(r->leader_state.progress);
         r->leader_state.progress = NULL;

diff --git a/src/election.c b/src/election.c
@@ -6,12 +6,7 @@
 #include "log.h"
 #include "tracing.h"
 
-/* Set to 1 to enable tracing. */
-#if 0
 #define tracef(...) Tracef(r->tracer, __VA_ARGS__)
-#else
-#define tracef(...)
-#endif
 
 /* Common fields between follower and candidate state.
  *
@@ -131,6 +126,7 @@ int electionStart(struct raft *r)
         /* Reset vote */
         rv = r->io->set_vote(r->io, 0);
         if (rv != 0) {
+            tracef("set_vote failed %d", rv);
             goto err;
         }
         /* Update our cache too. */
@@ -140,12 +136,14 @@ int electionStart(struct raft *r)
         term = r->current_term + 1;
         rv = r->io->set_term(r->io, term);
         if (rv != 0) {
+            tracef("set_term failed %d", rv);
             goto err;
         }
 
         /* Vote for self */
         rv = r->io->set_vote(r->io, r->id);
         if (rv != 0) {
+            tracef("set_vote self failed %d", rv);
             goto err;
         }
 
@@ -264,6 +262,7 @@ int electionVote(struct raft *r,
     if (!args->pre_vote) {
         rv = r->io->set_vote(r->io, args->candidate_id);
         if (rv != 0) {
+            tracef("set_vote failed %d", rv);
             return rv;
         }
         r->voted_for = args->candidate_id;
@@ -272,6 +271,7 @@ int electionVote(struct raft *r,
         r->election_timer_start = r->io->time(r->io);
     }
 
+    tracef("vote granted to %llu", args->candidate_id);
     *granted = true;
 
     return 0;

diff --git a/src/fixture.c b/src/fixture.c
@@ -13,12 +13,7 @@
 #include "snapshot.h"
 #include "tracing.h"
 
-/* Set to 1 to enable tracing. */
-#if 0
 #define tracef(...) Tracef(r->tracer, __VA_ARGS__)
-#else
-#define tracef(...)
-#endif
 
 /* Defaults */
 #define HEARTBEAT_TIMEOUT 100

diff --git a/src/membership.c b/src/membership.c
@@ -6,22 +6,28 @@
 #include "err.h"
 #include "log.h"
 #include "progress.h"
+#include "tracing.h"
+
+#define tracef(...) Tracef(r->tracer, __VA_ARGS__)
 
 int membershipCanChangeConfiguration(struct raft *r)
 {
     int rv;
 
     if (r->state != RAFT_LEADER || r->transfer != NULL) {
+        tracef("NOT LEADER");
         rv = RAFT_NOTLEADER;
         goto err;
     }
 
     if (r->configuration_uncommitted_index != 0) {
+        tracef("r->configuration_uncommitted_index %llu", r->configuration_uncommitted_index);
         rv = RAFT_CANTCHANGE;
         goto err;
     }
 
     if (r->leader_state.promotee_id != 0) {
+        tracef("r->leader_state.promotee_id %llu", r->leader_state.promotee_id);
         rv = RAFT_CANTCHANGE;
         goto err;
     }
@@ -69,6 +75,8 @@ bool membershipUpdateCatchUpRound(struct raft *r)
     /* If the server did not reach the target index for this round, it did not
      * catch up. */
     if (match_index < r->leader_state.round_index) {
+        tracef("member (index: %u) not yet caught up match_index:%llu round_index:%llu",
+                server_index, match_index, r->leader_state.round_index);
         return false;
     }
 
@@ -78,6 +86,9 @@ bool membershipUpdateCatchUpRound(struct raft *r)
     is_up_to_date = match_index == last_index;
     is_fast_enough = round_duration < r->election_timeout;
 
+    tracef("member is_up_to_date:%d is_fast_enough:%d",
+            is_up_to_date, is_fast_enough);
+
     /* If the server's log is fully up-to-date or the round that just terminated
      * was fast enough, then the server as caught up. */
     if (is_up_to_date || is_fast_enough) {
@@ -114,8 +125,10 @@ int membershipUncommittedChange(struct raft *r,
 
     rv = configurationDecode(&entry->buf, &configuration);
     if (rv != 0) {
+        tracef("failed to decode configuration at index:%llu", index);
         goto err;
     }
+    configurationTrace(r, &configuration, "uncommitted config change");
 
     raft_configuration_close(&r->configuration);
 
@@ -137,6 +150,7 @@ int membershipRollback(struct raft *r)
     assert(r != NULL);
     assert(r->state == RAFT_FOLLOWER);
     assert(r->configuration_uncommitted_index > 0);
+    tracef("roll back membership");
 
     /* Fetch the last committed configuration entry. */
     assert(r->configuration_index != 0);
@@ -154,6 +168,8 @@ int membershipRollback(struct raft *r)
         return rv;
     }
 
+    configurationTrace(r, &r->configuration, "roll back config");
+
     r->configuration_uncommitted_index = 0;
 
     return 0;

diff --git a/src/progress.c b/src/progress.c
@@ -5,12 +5,7 @@
 #include "log.h"
 #include "tracing.h"
 
-/* Set to 1 to enable tracing. */
-#if 0
 #define tracef(...) Tracef(r->tracer, __VA_ARGS__)
-#else
-#define tracef(...)
-#endif
 
 #ifndef max
 #define max(a, b) ((a) < (b) ? (b) : (a))
@@ -126,6 +121,7 @@ bool progressShouldReplicate(struct raft *r, unsigned i)
         case PROGRESS__SNAPSHOT:
             /* Snapshot timed out, move to PROBE */
             if (now - p->snapshot_last_send >= r->install_snapshot_timeout) {
+                tracef("snapshot timed out for index:%u", i);
                 result = true;
                 progressAbortSnapshot(r, i);
             } else {

diff --git a/src/raft.c b/src/raft.c
@@ -35,7 +35,10 @@ int raft_init(struct raft *r,
     r->io = io;
     r->io->data = r;
     r->fsm = fsm;
-    r->tracer = &NoopTracer;
+
+    r->tracer = &StderrTracer;
+    raft_tracer_maybe_enable(r->tracer, true);
+
     r->id = id;
     /* Make a copy of the address */
     r->address = HeapMalloc(strlen(address) + 1);

diff --git a/src/recv.c b/src/recv.c
@@ -15,12 +15,7 @@
 #include "string.h"
 #include "tracing.h"
 
-/* Set to 1 to enable tracing. */
-#if 0
 #define tracef(...) Tracef(r->tracer, __VA_ARGS__)
-#else
-#define tracef(...)
-#endif
 
 /* Dispatch a single RPC message to the appropriate handler. */
 static int recvMessage(struct raft *r, struct raft_message *message)
@@ -78,8 +73,7 @@ static int recvMessage(struct raft *r, struct raft_message *message)
     };
 
     if (rv != 0 && rv != RAFT_NOCONNECTION) {
-        /* tracef("recv: %s: %s", message_descs[message->type - 1],
-                 raft_strerror(rv)); */
+        tracef("recv: %d: %s", message->type, raft_strerror(rv));
         return rv;
     }
 
@@ -171,6 +165,7 @@ int recvEnsureMatchingTerms(struct raft *r, raft_term term, int *match)
     recvCheckMatchingTerms(r, term, match);
 
     if (*match == -1) {
+        tracef("old term - current_term:%llu other_term:%llu", r->current_term, term);
         return 0;
     }
 
@@ -191,6 +186,7 @@ int recvEnsureMatchingTerms(struct raft *r, raft_term term, int *match)
     if (*match == 1) {
         rv = recvBumpCurrentTerm(r, term);
         if (rv != 0) {
+            tracef("recvBumpCurrentTerm failed %d", rv);
             return rv;
         }
     }