test: Convert election test cases to v1 API

Signed-off-by: Free Ekanayaka <free@ekanayaka.io>

include/raft.h

@@ -1182,7 +1182,7 @@ RAFT_API int raft_start(struct raft *r);
  *   keeps split votes rates under 40% in all cases for reasonably sized
  *   clusters, and typically results in much lower rates.
  *
- * Note that the current random election timer will be reset and a new one timer
+ * Note that the current random election timer will be reset and a new one
  * will be generated.
  */
 RAFT_API void raft_set_election_timeout(struct raft *r, unsigned msecs);

src/client.c

@@ -72,8 +72,12 @@ int ClientSubmit(struct raft *r, struct raft_entry *entries, unsigned n)
     /* Index of the first entry being appended. */
     index = logLastIndex(r->log) + 1;
 
-    infof("persist %u entries with first index %lld at term %lld", n, index,
-          entries[0].term);
+    if (n == 1) {
+        infof("replicate 1 new entry (%llu^%llu)", index, entries[0].term);
+    } else {
+        infof("replicate %u new entries (%llu^%llu..%llu^%llu)", n, index,
+              entries[0].term, index + n - 1, entries[n - 1].term);
+    }
 
     for (i = 0; i < n; i++) {
         struct raft_entry *entry = &entries[i];

src/election.c

@@ -33,14 +33,19 @@ struct followerOrCandidateState *getFollowerOrCandidateState(struct raft *r)
     return state;
 }
 
-void electionResetTimer(struct raft *r)
+void electionUpdateRandomizedTimeout(struct raft *r)
 {
     struct followerOrCandidateState *state = getFollowerOrCandidateState(r);
     unsigned timeout = RandomWithinRange(&r->random, r->election_timeout,
                                          2 * r->election_timeout);
     assert(timeout >= r->election_timeout);
     assert(timeout <= r->election_timeout * 2);
     state->randomized_election_timeout = timeout;
+}
+
+void electionResetTimer(struct raft *r)
+{
+    electionUpdateRandomizedTimeout(r);
     r->election_timer_start = r->now;
     r->update->flags |= RAFT_UPDATE_TIMEOUT;
 }
@@ -204,7 +209,8 @@ int electionVote(struct raft *r,
         r->transfer != NULL && r->transfer->id == args->candidate_id;
     if (!args->pre_vote && r->voted_for != 0 &&
         r->voted_for != args->candidate_id && !is_transferee) {
-        tracef("local server already voted -> not granting vote");
+        infof("already voted for server %llu -> don't grant vote",
+              r->voted_for);
         return 0;
     }
 
@@ -234,10 +240,9 @@ int electionVote(struct raft *r,
 
     if (args->last_log_term < local_last_term) {
         /* The requesting server has last entry's log term lower than ours. */
-        tracef(
-            "local last entry %llu has term %llu higher than %llu -> not "
-            "granting",
-            local_last_index, local_last_term, args->last_log_term);
+        infof("remote log older (%llu^%llu vs %llu^%llu) -> don't grant vote",
+              args->last_log_index, args->last_log_term, local_last_index,
+              local_last_term);
         return 0;
     }
 
@@ -257,13 +262,15 @@ int electionVote(struct raft *r,
     if (local_last_index <= args->last_log_index) {
         /* Our log is shorter or equal to the one of the requester. */
         infof(
-            "remote log equal or longer (%llu.%llu vs %llu.%llu) -> grant vote",
+            "remote log equal or longer (%llu^%llu vs %llu^%llu) -> grant vote",
             args->last_log_index, args->last_log_term, local_last_index,
             local_last_term);
         goto grant_vote;
     }
 
-    tracef("remote log shorter than local -> not granting vote");
+    infof("remote log shorter (%llu^%llu vs %llu^%llu) -> don't grant vote",
+          args->last_log_index, args->last_log_term, local_last_index,
+          local_last_term);
 
     return 0;
 
@@ -279,31 +286,36 @@ int electionVote(struct raft *r,
         r->update->flags |= RAFT_UPDATE_TIMEOUT;
     }
 
-    tracef("vote granted to %llu", args->candidate_id);
     *granted = true;
 
     return 0;
 }
 
-bool electionTally(struct raft *r, size_t voter_index)
+bool electionTally(struct raft *r,
+                   size_t voter_index,
+                   unsigned *votes,
+                   unsigned *n_voters)
 {
-    size_t n_voters = configurationVoterCount(&r->configuration);
-    size_t votes = 0;
+    size_t half;
     size_t i;
-    size_t half = n_voters / 2;
+
+    *n_voters = configurationVoterCount(&r->configuration);
+    *votes = 0;
+
+    half = *n_voters / 2;
 
     assert(r->state == RAFT_CANDIDATE);
     assert(r->candidate_state.votes != NULL);
 
     r->candidate_state.votes[voter_index] = true;
 
-    for (i = 0; i < n_voters; i++) {
+    for (i = 0; i < *n_voters; i++) {
         if (r->candidate_state.votes[i]) {
-            votes++;
+            *votes += 1;
         }
     }
 
-    return votes >= half + 1;
+    return *votes >= half + 1;
 }
 
 #undef infof

src/election.h

@@ -5,6 +5,11 @@
 
 #include "../include/raft.h"
 
+/* This function must be called after the election timeout value has been
+ * changed and the server is in follower or candidate state. It generates a new
+ * value of the randomized election timeout. */
+void electionUpdateRandomizedTimeout(struct raft *r);
+
 /* Reset the election_timer clock and set randomized_election_timeout to a
  * random value between election_timeout and 2 * election_timeout.
  *
@@ -80,7 +85,13 @@ int electionVote(struct raft *r,
 
 /* Update the votes array by adding the vote from the server at the given
  * index. Return true if with this vote the server has reached the majority of
- * votes and won elections. */
-bool electionTally(struct raft *r, size_t voter_index);
+ * votes and won elections.
+ *
+ * The 'votes' and 'n_voters' output parameters indicate how many votes the
+ * server has and how many voters are there. */
+bool electionTally(struct raft *r,
+                   size_t voter_index,
+                   unsigned *votes,
+                   unsigned *n_voters);
 
 #endif /* ELECTION_H_ */

src/raft.c

@@ -208,30 +208,56 @@ static int maybeSelfElect(struct raft *r)
 /* Emit a start message containing information about the current state. */
 static void stepStartEmitMessage(struct raft *r)
 {
-    char msg[512];
+    char msg[512] = {0};
+    raft_index snapshot_index = logSnapshotIndex(r->log);
+    unsigned n_entries = (unsigned)logNumEntries(r->log);
 
-    sprintf(msg, "term %llu, vote %llu, ", r->current_term, r->voted_for);
+    if (r->current_term == 0) {
+        strcat(msg, "no state");
+        goto emit;
+    }
+
+    if (r->current_term > 0) {
+        char msg_term[64];
+        sprintf(msg_term, "term %llu", r->current_term);
+        strcat(msg, msg_term);
+        if (snapshot_index > 0 || n_entries > 0) {
+            strcat(msg, ", ");
+        }
+    }
+
+    if (r->voted_for > 0) {
+        char msg_vote[64];
+        sprintf(msg_vote, "voted for %llu, ", r->voted_for);
+        strcat(msg, msg_vote);
+    }
 
     if (logSnapshotIndex(r->log) > 0) {
         char msg_snapshot[64];
-        sprintf(msg_snapshot, "snapshot %llu.%llu, ", logSnapshotIndex(r->log),
-                logSnapshotTerm(r->log));
+        sprintf(msg_snapshot, "1 snapshot (%llu^%llu)",
+                logSnapshotIndex(r->log), logSnapshotTerm(r->log));
         strcat(msg, msg_snapshot);
-    } else {
-        strcat(msg, "no snapshot, ");
+        if (n_entries > 0) {
+            strcat(msg, ", ");
+        }
     }
 
-    if (logNumEntries(r->log)) {
+    if (n_entries > 0) {
         char msg_entries[64];
         raft_index first = logLastIndex(r->log) - logNumEntries(r->log) + 1;
-        raft_index last = logLastIndex(r->log);
-        sprintf(msg_entries, "entries %llu.%llu to %llu.%llu", first,
-                logTermOf(r->log, first), last, logTermOf(r->log, last));
+        if (n_entries == 1) {
+            sprintf(msg_entries, "1 entry (%llu^%llu)", first,
+                    logTermOf(r->log, first));
+        } else {
+            raft_index last = logLastIndex(r->log);
+            sprintf(msg_entries, "%u entries (%llu^%llu..%llu^%llu)", n_entries,
+                    first, logTermOf(r->log, first), last,
+                    logTermOf(r->log, last));
+        }
         strcat(msg, msg_entries);
-    } else {
-        strcat(msg, "no entries");
     }
 
+emit:
     infof("%s", msg);
 }
 
@@ -251,6 +277,13 @@ static int stepStart(struct raft *r,
     r->current_term = term;
     r->voted_for = voted_for;
 
+    /* If no term is set, there must be no persisted state. */
+    if (r->current_term == 0) {
+        assert(r->voted_for == 0);
+        assert(metadata == NULL);
+        assert(n_entries == 0);
+    }
+
     if (metadata != NULL) {
         snapshot_index = metadata->index;
         snapshot_term = metadata->term;
@@ -297,6 +330,32 @@ static int stepStart(struct raft *r,
     return 0;
 }
 
+static int stepPersistedEntries(struct raft *r,
+                                raft_index index,
+                                struct raft_entry *entries,
+                                unsigned n,
+                                int status)
+{
+    raft_index last_stored = r->last_stored + n;
+    raft_index last_index = logLastIndex(r->log);
+    int rv;
+
+    assert(n > 0);
+    assert(last_stored > 0);
+    assert(last_index > 0);
+
+    if (n == 1) {
+        infof("persisted 1 entry (%llu^%llu)", index, entries[0].term);
+    } else {
+        infof("persisted %u entry (%llu^%llu..%llu^%llu)", n, index,
+              entries[0].term, index + n - 1, entries[n - 1].term);
+    }
+
+    rv = replicationPersistEntriesDone(r, index, entries, n, status);
+
+    return rv;
+}
+
 /* Handle the completion of a send message operation. */
 static int stepSent(struct raft *r, struct raft_message *message, int status)
 {
@@ -388,10 +447,10 @@ int raft_step(struct raft *r,
             rv = 0;
             break;
         case RAFT_PERSISTED_ENTRIES:
-            rv = replicationPersistEntriesDone(
-                r, event->persisted_entries.index,
-                event->persisted_entries.batch, event->persisted_entries.n,
-                event->persisted_entries.status);
+            rv = stepPersistedEntries(r, event->persisted_entries.index,
+                                      event->persisted_entries.batch,
+                                      event->persisted_entries.n,
+                                      event->persisted_entries.status);
             break;
         case RAFT_PERSISTED_SNAPSHOT:
             rv = replicationPersistSnapshotDone(
@@ -505,13 +564,21 @@ int raft_catch_up(struct raft *r, raft_id id, int *status)
 void raft_set_election_timeout(struct raft *r, const unsigned msecs)
 {
     r->election_timeout = msecs;
+
     /* FIXME: workaround for failures in the dqlite test suite, which sets
      * timeouts too low and end up in failures when run on slow harder. */
     if (r->io != NULL && r->election_timeout == 150 &&
         r->heartbeat_timeout == 15) {
         r->election_timeout *= 3;
         r->heartbeat_timeout *= 3;
     }
+
+    switch (r->state) {
+        case RAFT_FOLLOWER:
+        case RAFT_CANDIDATE:
+            electionUpdateRandomizedTimeout(r);
+            break;
+    }
 }
 
 void raft_set_heartbeat_timeout(struct raft *r, const unsigned msecs)

src/recv.c

@@ -130,7 +130,7 @@ int recvBumpCurrentTerm(struct raft *r, raft_term term)
     sprintf(msg, "remote term is higher (%lld vs %lld) -> bump term", term,
             r->current_term);
     if (r->state != RAFT_FOLLOWER) {
-        strcat(msg, " and step down");
+        strcat(msg, ", step down");
     }
     infof("%s", msg);
 

src/recv_append_entries.c

@@ -28,11 +28,6 @@ int recvAppendEntries(struct raft *r,
     assert(id > 0);
     assert(args != NULL);
     assert(address != NULL);
-    tracef(
-        "self:%llu from:%llu@%s leader_commit:%llu n_entries:%d "
-        "prev_log_index:%llu prev_log_term:%llu, term:%llu",
-        r->id, id, address, args->leader_commit, args->n_entries,
-        args->prev_log_index, args->prev_log_term, args->term);
 
     result->rejected = args->prev_log_index;
     result->last_log_index = logLastIndex(r->log);

src/recv_request_vote.c

@@ -7,6 +7,7 @@
 #include "replication.h"
 #include "tracing.h"
 
+#define infof(...) Infof(r->tracer, "  " __VA_ARGS__)
 #define tracef(...) Tracef(r->tracer, __VA_ARGS__)
 
 int recvRequestVote(struct raft *r,
@@ -57,7 +58,13 @@ int recvRequestVote(struct raft *r,
         r->state == RAFT_LEADER ||
         (r->state == RAFT_FOLLOWER && r->follower_state.current_leader.id != 0);
     if (has_leader && !args->disrupt_leader) {
-        tracef("local server has a leader -> reject ");
+        if (r->state == RAFT_LEADER) {
+            infof("local server is leader -> reject");
+        } else {
+            assert(r->state == RAFT_FOLLOWER);
+            infof("local server has a leader (server %llu) -> reject",
+                  r->follower_state.current_leader.id);
+        }
         goto reply;
     }
 
@@ -90,7 +97,8 @@ int recvRequestVote(struct raft *r,
      *
      */
     if (match < 0) {
-        tracef("local term is higher -> reject ");
+        infof("remote term is lower (%llu vs %llu) -> reject", args->term,
+              r->current_term);
         goto reply;
     }
 
@@ -134,4 +142,5 @@ int recvRequestVote(struct raft *r,
     return 0;
 }
 
+#undef infof
 #undef tracef