Commit 1297265f authored by Willem Thiart's avatar Willem Thiart
Browse files

Add better logging; Fix leader election failure

parent f123874b
...@@ -173,12 +173,14 @@ typedef int ( ...@@ -173,12 +173,14 @@ typedef int (
/** Callback for providing debug logging information. /** Callback for providing debug logging information.
* This callback is optional * This callback is optional
* @param[in] raft The Raft server making this callback * @param[in] raft The Raft server making this callback
* @param[in] node The node that is the subject of this log. Could be NULL.
* @param[in] user_data User data that is passed from Raft server * @param[in] user_data User data that is passed from Raft server
* @param[in] buf The buffer that was logged */ * @param[in] buf The buffer that was logged */
typedef void ( typedef void (
*func_log_f *func_log_f
) ( ) (
raft_server_t* raft, raft_server_t* raft,
raft_node_t* node,
void *user_data, void *user_data,
const char *buf const char *buf
); );
...@@ -563,4 +565,12 @@ int raft_get_state(raft_server_t* me_); ...@@ -563,4 +565,12 @@ int raft_get_state(raft_server_t* me_);
* @return the last log term */ * @return the last log term */
int raft_get_last_log_term(raft_server_t* me_); int raft_get_last_log_term(raft_server_t* me_);
/** Tell if we are a leader, candidate or follower.
* @return get state of type raft_state_e. */
int raft_get_state(raft_server_t* me_);
/** The the most recent log's term
* @return the last log term */
int raft_get_last_log_term(raft_server_t* me_);
#endif /* RAFT_H_ */ #endif /* RAFT_H_ */
...@@ -24,7 +24,7 @@ ...@@ -24,7 +24,7 @@
#define min(a, b) ((a) < (b) ? (a) : (b)) #define min(a, b) ((a) < (b) ? (a) : (b))
#define max(a, b) ((a) < (b) ? (b) : (a)) #define max(a, b) ((a) < (b) ? (b) : (a))
static void __log(raft_server_t *me_, const char *fmt, ...) static void __log(raft_server_t *me_, raft_node_t* node, const char *fmt, ...)
{ {
raft_server_private_t* me = (raft_server_private_t*)me_; raft_server_private_t* me = (raft_server_private_t*)me_;
char buf[1024]; char buf[1024];
...@@ -34,7 +34,7 @@ static void __log(raft_server_t *me_, const char *fmt, ...) ...@@ -34,7 +34,7 @@ static void __log(raft_server_t *me_, const char *fmt, ...)
vsprintf(buf, fmt, args); vsprintf(buf, fmt, args);
if (me->cb.log) if (me->cb.log)
me->cb.log(me_, me->udata, buf); me->cb.log(me_, node, me->udata, buf);
} }
raft_server_t* raft_new() raft_server_t* raft_new()
...@@ -75,8 +75,9 @@ void raft_election_start(raft_server_t* me_) ...@@ -75,8 +75,9 @@ void raft_election_start(raft_server_t* me_)
{ {
raft_server_private_t* me = (raft_server_private_t*)me_; raft_server_private_t* me = (raft_server_private_t*)me_;
__log(me_, "election starting: %d %d, term: %d", __log(me_, NULL, "election starting: %d %d, term: %d ci: %d",
me->election_timeout, me->timeout_elapsed, me->current_term); me->election_timeout, me->timeout_elapsed, me->current_term,
raft_get_current_idx(me_));
raft_become_candidate(me_); raft_become_candidate(me_);
} }
...@@ -86,7 +87,7 @@ void raft_become_leader(raft_server_t* me_) ...@@ -86,7 +87,7 @@ void raft_become_leader(raft_server_t* me_)
raft_server_private_t* me = (raft_server_private_t*)me_; raft_server_private_t* me = (raft_server_private_t*)me_;
int i; int i;
__log(me_, "becoming leader"); __log(me_, NULL, "becoming leader term:%d", raft_get_current_term(me_));
raft_set_state(me_, RAFT_STATE_LEADER); raft_set_state(me_, RAFT_STATE_LEADER);
for (i = 0; i < me->num_nodes; i++) for (i = 0; i < me->num_nodes; i++)
...@@ -106,11 +107,11 @@ void raft_become_candidate(raft_server_t* me_) ...@@ -106,11 +107,11 @@ void raft_become_candidate(raft_server_t* me_)
raft_server_private_t* me = (raft_server_private_t*)me_; raft_server_private_t* me = (raft_server_private_t*)me_;
int i; int i;
__log(me_, "becoming candidate"); __log(me_, NULL, "becoming candidate");
raft_set_current_term(me_, raft_get_current_term(me_) + 1);
for (i = 0; i < me->num_nodes; i++) for (i = 0; i < me->num_nodes; i++)
raft_node_vote_for_me(me->nodes[i], 0); raft_node_vote_for_me(me->nodes[i], 0);
me->current_term += 1;
raft_vote(me_, me->node); raft_vote(me_, me->node);
me->current_leader = NULL; me->current_leader = NULL;
raft_set_state(me_, RAFT_STATE_CANDIDATE); raft_set_state(me_, RAFT_STATE_CANDIDATE);
...@@ -126,7 +127,7 @@ void raft_become_candidate(raft_server_t* me_) ...@@ -126,7 +127,7 @@ void raft_become_candidate(raft_server_t* me_)
void raft_become_follower(raft_server_t* me_) void raft_become_follower(raft_server_t* me_)
{ {
__log(me_, "becoming follower"); __log(me_, NULL, "becoming follower");
raft_set_state(me_, RAFT_STATE_FOLLOWER); raft_set_state(me_, RAFT_STATE_FOLLOWER);
} }
...@@ -171,9 +172,11 @@ int raft_recv_appendentries_response(raft_server_t* me_, ...@@ -171,9 +172,11 @@ int raft_recv_appendentries_response(raft_server_t* me_,
assert(node); assert(node);
assert(node != me->node); assert(node != me->node);
__log(me_, __log(me_, node,
"received appendentries response node: %d %s cidx: %d 1stidx: %d", "received appendentries response %s ci:%d rci:%d 1stidx:%d",
node, r->success == 1 ? "success" : "fail", r->current_idx, r->success == 1 ? "SUCCESS" : "fail",
raft_get_current_idx(me_),
r->current_idx,
r->first_idx); r->first_idx);
if (!raft_is_leader(me_)) if (!raft_is_leader(me_))
...@@ -263,9 +266,10 @@ int raft_recv_appendentries( ...@@ -263,9 +266,10 @@ int raft_recv_appendentries(
me->timeout_elapsed = 0; me->timeout_elapsed = 0;
if (0 < ae->n_entries) if (0 < ae->n_entries)
__log(me_, "recvd appendentries from: %d, %d %d %d %d #%d", __log(me_, node, "recvd appendentries from: %lx, t:%d ci:%d lc:%d pli:%d plt:%d #%d",
node, node,
ae->term, ae->term,
raft_get_current_idx(me_),
ae->leader_commit, ae->leader_commit,
ae->prev_log_idx, ae->prev_log_idx,
ae->prev_log_term, ae->prev_log_term,
...@@ -286,7 +290,8 @@ int raft_recv_appendentries( ...@@ -286,7 +290,8 @@ int raft_recv_appendentries(
else if (ae->term < me->current_term) else if (ae->term < me->current_term)
{ {
/* 1. Reply false if term < currentTerm (§5.1) */ /* 1. Reply false if term < currentTerm (§5.1) */
__log(me_, "AE term is less than current term"); __log(me_, node, "AE term %d is less than current term %d",
ae->term, me->current_term);
goto fail_with_current_idx; goto fail_with_current_idx;
} }
...@@ -298,7 +303,7 @@ int raft_recv_appendentries( ...@@ -298,7 +303,7 @@ int raft_recv_appendentries(
if (!e) if (!e)
{ {
__log(me_, "AE no log at prev_idx %d", ae->prev_log_idx); __log(me_, node, "AE no log at prev_idx %d", ae->prev_log_idx);
goto fail_with_current_idx; goto fail_with_current_idx;
} }
...@@ -309,8 +314,8 @@ int raft_recv_appendentries( ...@@ -309,8 +314,8 @@ int raft_recv_appendentries(
if (e->term != ae->prev_log_term) if (e->term != ae->prev_log_term)
{ {
__log(me_, "AE term doesn't match prev_idx (ie. %d vs %d)", __log(me_, node, "AE term doesn't match prev_term (ie. %d vs %d) ci:%d pli:%d",
e->term, ae->prev_log_term); e->term, ae->prev_log_term, raft_get_current_idx(me_), ae->prev_log_idx);
assert(me->commit_idx < ae->prev_log_idx); assert(me->commit_idx < ae->prev_log_idx);
/* Delete all the following log entries because they don't match */ /* Delete all the following log entries because they don't match */
log_delete(me->log, ae->prev_log_idx); log_delete(me->log, ae->prev_log_idx);
...@@ -438,7 +443,7 @@ int raft_recv_requestvote(raft_server_t* me_, ...@@ -438,7 +443,7 @@ int raft_recv_requestvote(raft_server_t* me_,
else else
r->vote_granted = 0; r->vote_granted = 0;
__log(me_, "node requested vote: %d replying: %s", __log(me_, node, "node requested vote: %d replying: %s",
node, r->vote_granted == 1 ? "granted" : "not granted"); node, r->vote_granted == 1 ? "granted" : "not granted");
r->term = raft_get_current_term(me_); r->term = raft_get_current_term(me_);
...@@ -462,8 +467,8 @@ int raft_recv_requestvote_response(raft_server_t* me_, ...@@ -462,8 +467,8 @@ int raft_recv_requestvote_response(raft_server_t* me_,
assert(node); assert(node);
assert(node != me->node); assert(node != me->node);
__log(me_, "node responded to requestvote: %d status: %s", __log(me_, node, "node responded to requestvote status: %s",
node, r->vote_granted == 1 ? "granted" : "not granted"); r->vote_granted == 1 ? "granted" : "not granted");
if (!raft_is_candidate(me_)) if (!raft_is_candidate(me_))
return 0; return 0;
...@@ -482,6 +487,11 @@ int raft_recv_requestvote_response(raft_server_t* me_, ...@@ -482,6 +487,11 @@ int raft_recv_requestvote_response(raft_server_t* me_,
return 0; return 0;
} }
__log(me_, node, "node responded to requestvote: %d status: %s ct:%d rt:%d",
node, r->vote_granted == 1 ? "granted" : "not granted",
me->current_term,
r->term);
if (1 == r->vote_granted) if (1 == r->vote_granted)
{ {
raft_node_vote_for_me(node, 1); raft_node_vote_for_me(node, 1);
...@@ -502,7 +512,8 @@ int raft_recv_entry(raft_server_t* me_, raft_node_t* node, msg_entry_t* e, ...@@ -502,7 +512,8 @@ int raft_recv_entry(raft_server_t* me_, raft_node_t* node, msg_entry_t* e,
if (!raft_is_leader(me_)) if (!raft_is_leader(me_))
return -1; return -1;
__log(me_, "received entry from: %d", node); __log(me_, node, "received entry t:%d id: %d idx: %d",
me->current_term, e->id, raft_get_current_idx(me_) + 1, node);
raft_entry_t ety; raft_entry_t ety;
ety.term = me->current_term; ety.term = me->current_term;
...@@ -538,7 +549,7 @@ int raft_send_requestvote(raft_server_t* me_, raft_node_t* node) ...@@ -538,7 +549,7 @@ int raft_send_requestvote(raft_server_t* me_, raft_node_t* node)
assert(node); assert(node);
assert(node != me->node); assert(node != me->node);
__log(me_, "sending requestvote to: %d", node); __log(me_, node, "sending requestvote to: %d", node);
rv.term = me->current_term; rv.term = me->current_term;
rv.last_log_idx = raft_get_current_idx(me_); rv.last_log_idx = raft_get_current_idx(me_);
...@@ -567,7 +578,8 @@ int raft_apply_entry(raft_server_t* me_) ...@@ -567,7 +578,8 @@ int raft_apply_entry(raft_server_t* me_)
if (!e) if (!e)
return -1; return -1;
__log(me_, "applying log: %d, size: %d", me->last_applied_idx, e->data.len); __log(me_, NULL, "applying log: %d, id: %d size: %d",
me->last_applied_idx, e->id, e->data.len);
me->last_applied_idx++; me->last_applied_idx++;
if (me->cb.applylog) if (me->cb.applylog)
...@@ -618,8 +630,8 @@ int raft_send_appendentries(raft_server_t* me_, raft_node_t* node) ...@@ -618,8 +630,8 @@ int raft_send_appendentries(raft_server_t* me_, raft_node_t* node)
ae.prev_log_term = prev_ety->term; ae.prev_log_term = prev_ety->term;
} }
__log(me_, "sending appendentries node: %d, %d %d %d %d", __log(me_, node, "sending appendentries node: ci:%d t:%d lc:%d pli:%d plt:%d",
node, raft_get_current_idx(me_),
ae.term, ae.term,
ae.leader_commit, ae.leader_commit,
ae.prev_log_idx, ae.prev_log_idx,
...@@ -680,6 +692,8 @@ void raft_vote(raft_server_t* me_, raft_node_t* node) ...@@ -680,6 +692,8 @@ void raft_vote(raft_server_t* me_, raft_node_t* node)
{ {
raft_server_private_t* me = (raft_server_private_t*)me_; raft_server_private_t* me = (raft_server_private_t*)me_;
assert(!me->voted_for || node != me->voted_for);
me->voted_for = node; me->voted_for = node;
if (me->cb.persist_vote) if (me->cb.persist_vote)
me->cb.persist_vote(me_, me->udata, raft_node_get_id(node)); me->cb.persist_vote(me_, me->udata, raft_node_get_id(node));
......
...@@ -137,7 +137,7 @@ raft_node_t* raft_get_node(raft_server_t *me_, int nodeid) ...@@ -137,7 +137,7 @@ raft_node_t* raft_get_node(raft_server_t *me_, int nodeid)
raft_server_private_t* me = (raft_server_private_t*)me_; raft_server_private_t* me = (raft_server_private_t*)me_;
int i; int i;
for (i=0; i<me->num_nodes; i++) for (i = 0; i < me->num_nodes; i++)
if (nodeid == raft_node_get_id(me->nodes[i])) if (nodeid == raft_node_get_id(me->nodes[i]))
return me->nodes[i]; return me->nodes[i];
......
...@@ -1141,6 +1141,7 @@ void TestRaft_follower_dont_grant_vote_if_candidate_has_a_less_complete_log( ...@@ -1141,6 +1141,7 @@ void TestRaft_follower_dont_grant_vote_if_candidate_has_a_less_complete_log(
ety.data.buf = (unsigned char*)"aaa"; ety.data.buf = (unsigned char*)"aaa";
raft_append_entry(r, &ety); raft_append_entry(r, &ety);
ety.id = 101; ety.id = 101;
ety.term = 2;
raft_append_entry(r, &ety); raft_append_entry(r, &ety);
/* vote not granted */ /* vote not granted */
...@@ -1153,9 +1154,9 @@ void TestRaft_follower_dont_grant_vote_if_candidate_has_a_less_complete_log( ...@@ -1153,9 +1154,9 @@ void TestRaft_follower_dont_grant_vote_if_candidate_has_a_less_complete_log(
rv.term = 2; rv.term = 2;
rv.candidate_id = 1; rv.candidate_id = 1;
rv.last_log_idx = 1; rv.last_log_idx = 1;
rv.last_log_term = 2; rv.last_log_term = 3;
raft_recv_requestvote(r, raft_get_node(r, 2), &rv, &rvr); raft_recv_requestvote(r, raft_get_node(r, 2), &rv, &rvr);
CuAssertTrue(tc, 1 == rvr.vote_granted); CuAssertIntEquals(tc, 1, rvr.vote_granted);
} }
void TestRaft_candidate_becomes_candidate_is_candidate(CuTest * tc) void TestRaft_candidate_becomes_candidate_is_candidate(CuTest * tc)
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment