public void SetNodeRole(NodeState newState)
{
if (newState == NodeState.Candidate && !NodeOptions.EnableLeader)
{
Logger.LogWarning(NodeStateService.GetNodeLogId() + "Tried to promote to candidate but node has been disabled.");
return;
}
if (newState != NodeStateService.Role)
{
Logger.LogInformation(NodeStateService.GetNodeLogId() + "Node's role changed to " + newState.ToString());
NodeStateService.SetRole(newState);
switch (newState)
{
case NodeState.Candidate:
ResetTimer(_electionTimeoutTimer, ClusterOptions.ElectionTimeoutMs, ClusterOptions.ElectionTimeoutMs);
StopTimer(_heartbeatTimer);
NodeStateService.InCluster = false;
if (NodeStateService.IsBootstrapped)
{
StartElection();
}
else
{
Logger.LogWarning("Node could not start election as bootstrapping was not complete");
}
break;
case NodeState.Follower:
Random rand = new Random();
//On becoming a follower, wait 5 seconds to allow any other nodes to send out election time outs
ResetTimer(_electionTimeoutTimer, rand.Next(ClusterOptions.ElectionTimeoutMs, ClusterOptions.ElectionTimeoutMs * 2), ClusterOptions.ElectionTimeoutMs);
StopTimer(_heartbeatTimer);
TaskUtility.RestartTask(ref _commitTask, () => MonitorCommits());
break;
case NodeState.Leader:
NodeStateService.CurrentLeader = _nodeStorage.Id;
NodeStateService.ResetLeaderState();
ResetTimer(_heartbeatTimer, 0, ClusterOptions.ElectionTimeoutMs / 4);
StopTimer(_electionTimeoutTimer);
TaskUtility.RestartTask(ref _commitTask, () => MonitorCommits());
NodeStateService.InCluster = true;
TaskUtility.RestartTask(ref _nodeDiscoveryTask, () => NodeDiscoveryLoop());
_clusterConnectionPool.CheckClusterConnectionPool();
break;
case NodeState.Disabled:
StopTimer(_electionTimeoutTimer);
StopTimer(_heartbeatTimer);
break;
}
}
}
public async void StartElection()
{
try
{
var lastLogTerm = _nodeStorage.GetLastLogTerm();
if (_nodeStorage.CurrentTerm > lastLogTerm + 3)
{
Logger.LogInformation("Detected that the node is too far ahead of its last log (3), restarting election from the term of the last log term " + lastLogTerm);
_nodeStorage.SetCurrentTerm(lastLogTerm + 1);
}
else
{
_nodeStorage.SetCurrentTerm(_nodeStorage.CurrentTerm + 1);
}
//Vote for yourself
_nodeStorage.SetVotedFor(_nodeStorage.Id);
var election = new Election(_loggerFactory.CreateLogger <Election>(), TimeSpan.FromMilliseconds(ClusterOptions.LatencyToleranceMs), ClusterOptions.GetClusterUrls().Where(url => url != NodeStateService.Url));
var collectedNodes = await election.CollectVotes(
_nodeStorage.CurrentTerm,
_nodeStorage.Id,
_nodeStorage.GetLastLogIndex(),
_nodeStorage.GetLastLogTerm());
if (collectedNodes.Count() >= ClusterOptions.MinimumNodes - 1)
{
Logger.LogInformation(NodeStateService.GetNodeLogId() + "Recieved enough votes to be promoted, promoting to leader. Registered nodes: " + (collectedNodes.Count() + 1) + " collection nodes " + ClusterOptions.MinimumNodes);
StopTimer(_electionTimeoutTimer);
SetNodeRole(NodeState.Leader);
AddNodesToCluster(collectedNodes.Select(cn => new NodeInformation()
{
Id = cn.Key,
TransportAddress = cn.Value,
IsContactable = true,
Name = ""
}));
}
else
{
NodeStateService.CurrentLeader = null;
_nodeStorage.SetVotedFor(null);
SetNodeRole(NodeState.Follower);
}
}
catch (Exception e)
{
Logger.LogError("Failed to run election with error " + e.StackTrace);
}
}
public RequestVoteResponse RequestVoteRPCHandler(RequestVote requestVoteRPC)
{
var successful = false;
if (NodeStateService.IsBootstrapped)
{
//To requests might come in at the same time causing the VotedFor to not match
lock (VoteLock)
{
//Ref1 $5.2, $5.4
if (_nodeStorage.CurrentTerm <= requestVoteRPC.Term && ((_nodeStorage.VotedFor == null || _nodeStorage.VotedFor == requestVoteRPC.CandidateId) &&
(requestVoteRPC.LastLogIndex >= _nodeStorage.GetTotalLogCount() && requestVoteRPC.LastLogTerm >= _nodeStorage.GetLastLogTerm())))
{
_nodeStorage.SetVotedFor(requestVoteRPC.CandidateId);
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Voting for " + requestVoteRPC.CandidateId + " for term " + requestVoteRPC.Term);
SetNodeRole(NodeState.Follower);
_nodeStorage.SetCurrentTerm(requestVoteRPC.Term);
successful = true;
}
else if (_nodeStorage.CurrentTerm > requestVoteRPC.Term)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Rejected vote from " + requestVoteRPC.CandidateId + " as current term is greater (" + requestVoteRPC.Term + "<" + _nodeStorage.CurrentTerm + ")");
}
else if (requestVoteRPC.LastLogIndex < _nodeStorage.GetTotalLogCount() - 1)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Rejected vote from " + requestVoteRPC.CandidateId + " as last log index is less then local index (" + requestVoteRPC.LastLogIndex + "<" + (_nodeStorage.GetTotalLogCount() - 1) + ")");
}
else if (requestVoteRPC.LastLogTerm < _nodeStorage.GetLastLogTerm())
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Rejected vote from " + requestVoteRPC.CandidateId + " as last log term is less then local term (" + requestVoteRPC.LastLogTerm + "<" + _nodeStorage.GetLastLogTerm() + ")");
}
else if ((_nodeStorage.VotedFor != null && _nodeStorage.VotedFor != requestVoteRPC.CandidateId))
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Rejected vote from " + requestVoteRPC.CandidateId + " as I have already voted for " + _nodeStorage.VotedFor + " | ");
}
else if (!successful)
{
Logger.LogError("Rejected vote from " + requestVoteRPC.CandidateId + " due to unknown reason.");
}
}
}
return(new RequestVoteResponse()
{
NodeId = _nodeStorage.Id,
IsSuccessful = successful
});
}
public async Task MonitorCommits(bool loop = true)
{
do
{
try
{
lock (commitLock)
{
_commitService.ApplyCommits();
if (NodeStateService.Role == NodeState.Leader || NodeStateService.Role == NodeState.Follower)
{
_snapshotService.CheckAndApplySnapshots(NodeStateService.CommitIndex, ClusterOptions.SnapshottingTrailingLogCount, ClusterOptions.SnapshottingInterval);
}
}
await Task.Delay(5);
}
catch (Exception e)
{
Logger.LogWarning(NodeStateService.GetNodeLogId() + " encountered error " + e.Message + " with stacktrace " + e.StackTrace);
}
}while (loop);
}
public async Task <ExecuteCommandsResponse> ExecuteCommandsRPCHandler(ExecuteCommands request)
{
int index = _nodeStorage.AddCommands(request.Commands.ToArray(), _nodeStorage.CurrentTerm);
var startDate = DateTime.Now;
while (request.WaitForCommits)
{
if ((startDate - DateTime.Now).TotalMilliseconds > ClusterOptions.CommitsTimeout)
{
return(new ExecuteCommandsResponse()
{
EntryNo = index,
IsSuccessful = false
});
}
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Waiting for " + request.RequestName + " to complete.");
if (NodeStateService.CommitIndex >= index)
{
return(new ExecuteCommandsResponse()
{
EntryNo = index,
IsSuccessful = true
});
}
else
{
await Task.Delay(100);
}
}
return(new ExecuteCommandsResponse()
{
EntryNo = index,
IsSuccessful = true
});
}
public async void SendHeartbeats()
{
if (NodeStateService.Role != NodeState.Leader)
{
Logger.LogWarning("Detected request to send hearbeat as non-leader");
return;
}
var startTime = DateTime.Now;
var recognizedhosts = 1;
ConcurrentBag <Guid> unreachableNodes = new ConcurrentBag <Guid>();
var clients = _clusterConnectionPool.GetAllNodeClients();
if (clients.Count() < StateMachine.GetNodes().Count())
{
_clusterConnectionPool.CheckClusterConnectionPool();
clients = _clusterConnectionPool.GetAllNodeClients();
}
var tasks = clients.Where(nc => nc.Key != _nodeStorage.Id && nc.Value.Address != NodeStateService.Url).Select(async node =>
{
try
{
//Add the match index if required
if (!NodeStateService.NextIndex.ContainsKey(node.Key))
{
NodeStateService.NextIndex.Add(node.Key, _nodeStorage.GetTotalLogCount() + 1);
}
if (!NodeStateService.MatchIndex.ContainsKey(node.Key))
{
NodeStateService.MatchIndex.TryAdd(node.Key, 0);
}
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Sending heartbeat to " + node.Key);
var entriesToSend = new List <LogEntry>();
var prevLogIndex = Math.Max(0, NodeStateService.NextIndex[node.Key] - 1);
var startingLogsToSend = NodeStateService.NextIndex[node.Key] == 0 ? 1 : NodeStateService.NextIndex[node.Key];
//if (startingLogsToSend <= _nodeStorage.GetTotalLogCount())
// {
if (_nodeStorage.LastSnapshotIncludedIndex < startingLogsToSend)
{
var unsentLogs = _nodeStorage.GetTotalLogCount() - startingLogsToSend;
int endingLogsToSend = (startingLogsToSend + (unsentLogs < ClusterOptions.MaxLogsToSend ? unsentLogs : ClusterOptions.MaxLogsToSend));
int prevLogTerm = 0;
if (_nodeStorage.LastSnapshotIncludedIndex == prevLogIndex)
{
prevLogTerm = _nodeStorage.LastSnapshotIncludedTerm;
}
else
{
prevLogTerm = (_nodeStorage.GetTotalLogCount() > 0 && prevLogIndex > 0) ? _nodeStorage.GetLogAtIndex(prevLogIndex).Term : 0;
}
if (NodeStateService.NextIndex[node.Key] <= _nodeStorage.GetLastLogIndex() && _nodeStorage.GetLastLogIndex() != 0 && !LogsSent.GetOrAdd(node.Key, false))
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + node.Key + " Requires logs from " + startingLogsToSend + " to " + endingLogsToSend);
entriesToSend = _nodeStorage.GetLogRange(startingLogsToSend, endingLogsToSend).OrderBy(log => log.Index).ToList();
// entriesToSend = _nodeStorage.Logs.Where(l => l.Index >= NextIndex[connector.Key]).ToList();
//Logger.LogDebug(NodeStateService.GetNodeLogId() + "Detected node " + node.Key + " is not upto date, sending logs from " + entriesToSend.First().Index + " to " + entriesToSend.Last().Index);
}
// Console.WriteLine("Sending logs with from " + entriesToSend.First().Index + " to " + entriesToSend.Last().Index + " sent " + entriesToSend.Count + "logs.");
LogsSent.AddOrUpdate(node.Key, true, (key, oldvalue) =>
{
return(true);
});
var result = await _clusterClient.Send(node.Key, new AppendEntry()
{
Term = _nodeStorage.CurrentTerm,
Entries = entriesToSend,
LeaderCommit = NodeStateService.CommitIndex,
LeaderId = _nodeStorage.Id,
PrevLogIndex = prevLogIndex,
PrevLogTerm = prevLogTerm
});
LogsSent.TryUpdate(node.Key, false, true);
if (result != null && node.Key != result.NodeId && result.NodeId != default(Guid))
{
Logger.LogInformation("Detected change of client");
RemoveNodesFromCluster(new Guid[] { node.Key });
AddNodesToCluster(new NodeInformation[] { new NodeInformation {
Id = result.NodeId,
TransportAddress = node.Value.Address,
IsContactable = true,
Name = "",
} });
}
if (result == null)
{
Logger.LogError(NodeStateService.GetNodeLogId() + "The node " + node.Key + " has returned a empty response");
}
else if (result != null && result.IsSuccessful)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Successfully updated logs on " + node.Key);
if (entriesToSend.Count() > 0)
{
var lastIndexToSend = entriesToSend.Last().Index;
NodeStateService.NextIndex[node.Key] = lastIndexToSend + 1;
int previousValue;
bool SuccessfullyGotValue = NodeStateService.MatchIndex.TryGetValue(node.Key, out previousValue);
if (!SuccessfullyGotValue)
{
Logger.LogError("Concurrency issues encountered when getting the Next Match Index");
}
var updateWorked = NodeStateService.MatchIndex.TryUpdate(node.Key, lastIndexToSend, previousValue);
//If the updated did not execute, there hs been a concurrency issue
while (!updateWorked)
{
SuccessfullyGotValue = NodeStateService.MatchIndex.TryGetValue(node.Key, out previousValue);
// If the match index has already exceeded the previous value, dont bother updating it
if (previousValue > lastIndexToSend && SuccessfullyGotValue)
{
updateWorked = true;
}
else
{
updateWorked = NodeStateService.MatchIndex.TryUpdate(node.Key, lastIndexToSend, previousValue);
}
}
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Updated match index to " + NodeStateService.MatchIndex);
}
}
else if (result.ConflictName == AppendEntriesExceptionNames.MissingLogEntryException)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Detected node " + node.Key + " is missing the previous log, sending logs from log " + (result.LastLogEntryIndex.Value + 1));
NodeStateService.NextIndex[node.Key] = (result.LastLogEntryIndex.Value + 1);
}
else if (result.ConflictName == AppendEntriesExceptionNames.ConflictingLogEntryException)
{
var firstEntryOfTerm = _nodeStorage.Logs.Where(l => l.Value.Term == result.ConflictingTerm).FirstOrDefault();
var revertedIndex = firstEntryOfTerm.Value.Index < result.FirstTermIndex ? firstEntryOfTerm.Value.Index : result.FirstTermIndex.Value;
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Detected node " + node.Key + " has conflicting values, reverting to " + revertedIndex);
//Revert back to the first index of that term
NodeStateService.NextIndex[node.Key] = revertedIndex;
}
else if (result.ConflictName == AppendEntriesExceptionNames.OldTermException)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Detected node " + node.Key + " rejected heartbeat due to invalid leader term.");
}
}
else
{
Logger.LogInformation("Detected pending snapshot to send, sending snapshot with included index " + _nodeStorage.LastSnapshotIncludedIndex);
//Mark that you have send the logs to this node
LogsSent.AddOrUpdate(node.Key, true, (key, oldvalue) =>
{
return(true);
});
var lastIndex = _nodeStorage.LastSnapshotIncludedIndex;
var result = await _clusterClient.Send(node.Key, new InstallSnapshot()
{
Term = _nodeStorage.CurrentTerm,
LastIncludedIndex = lastIndex,
LastIncludedTerm = _nodeStorage.LastSnapshotIncludedTerm,
LeaderId = _nodeStorage.Id,
Snapshot = _nodeStorage.LastSnapshot
});
if (result.IsSuccessful)
{
//mark the node has successfully received the logs
LogsSent.TryUpdate(node.Key, false, true);
NodeStateService.NextIndex[node.Key] = lastIndex + 1;
}
}
/* }
* //The node is up to date
* else
* {
* var result = await _clusterClient.Send(node.Key, new AppendEntry()
* {
* Term = _nodeStorage.CurrentTerm,
* Entries = entriesToSend,
* LeaderCommit = NodeStateService.CommitIndex,
* LeaderId = _nodeStorage.Id,
* PrevLogIndex = prevLogIndex,
* PrevLogTerm = _nodeStorage.GetLogAtIndex(prevLogIndex).Term
* });
* }
*/
Interlocked.Increment(ref recognizedhosts);
}
catch (HttpRequestException e)
{
unreachableNodes.Add(node.Key);
Logger.LogWarning(NodeStateService.GetNodeLogId() + "Heartbeat to node " + node.Key + " had a connection issue.");
}
catch (TaskCanceledException e)
{
unreachableNodes.Add(node.Key);
Logger.LogWarning(NodeStateService.GetNodeLogId() + "Heartbeat to node " + node.Key + " timed out");
}
catch (Exception e)
{
unreachableNodes.Add(node.Key);
Logger.LogWarning(NodeStateService.GetNodeLogId() + "Encountered error while sending heartbeat to node " + node.Key + ", request failed with error \"" + e.GetType().Name + e.Message + Environment.NewLine + e.StackTrace);//+ "\"" + e.StackTrace);
}
});
await Task.WhenAll(tasks);
//If less then the required number recognize the request, go back to being a candidate
if (recognizedhosts < ClusterOptions.MinimumNodes)
{
SetNodeRole(NodeState.Candidate);
}
else
{
//RemoveNodesFromCluster(unreachableNodes.ToList());
}
}
public AppendEntryResponse AppendEntryRPCHandler(AppendEntry entry)
{
//Check the log check to prevent a intermittent term increase with no back tracking, TODO check whether this causes potentially concurrency issues
if (entry.Term < _nodeStorage.CurrentTerm && entry.LeaderCommit <= NodeStateService.CommitIndex)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Rejected RPC from " + entry.LeaderId + " due to lower term " + entry.Term + "<" + _nodeStorage.CurrentTerm);
return(new AppendEntryResponse()
{
ConflictName = AppendEntriesExceptionNames.OldTermException,
NodeId = _nodeStorage.Id,
IsSuccessful = false
});
}
//Reset the timer if the append is from a valid term
ResetTimer(_electionTimeoutTimer, ClusterOptions.ElectionTimeoutMs, ClusterOptions.ElectionTimeoutMs);
//If you are a leader or candidate, swap to a follower
if (NodeStateService.Role == NodeState.Candidate || NodeStateService.Role == NodeState.Leader)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + " detected node " + entry.LeaderId + " is further ahead. Changing to follower");
SetNodeRole(NodeState.Follower);
}
if (NodeStateService.CurrentLeader != entry.LeaderId)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Detected uncontacted leader, discovering leader now.");
//Reset the current leader
NodeStateService.CurrentLeader = entry.LeaderId;
}
if (entry.LeaderCommit > NodeStateService.LatestLeaderCommit)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Detected leader commit of " + entry.LeaderCommit + " commiting data on node.");
NodeStateService.LatestLeaderCommit = entry.LeaderCommit;
}
// If your log entry is not within the last snapshot, then check the validity of the previous log index
if (_nodeStorage.LastSnapshotIncludedIndex < entry.PrevLogIndex)
{
var previousEntry = _nodeStorage.GetLogAtIndex(entry.PrevLogIndex);
if (previousEntry == null && entry.PrevLogIndex != 0)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Missing previous entry at index " + entry.PrevLogIndex + " from term " + entry.PrevLogTerm + " does not exist.");
return(new AppendEntryResponse()
{
IsSuccessful = false,
ConflictingTerm = null,
ConflictName = AppendEntriesExceptionNames.MissingLogEntryException,
FirstTermIndex = null,
NodeId = _nodeStorage.Id,
LastLogEntryIndex = _nodeStorage.GetTotalLogCount()
});
}
}
else
{
if (_nodeStorage.LastSnapshotIncludedTerm != entry.PrevLogTerm)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Inconsistency found in the node snapshot and leaders logs, log " + entry.PrevLogIndex + " from term " + entry.PrevLogTerm + " does not exist.");
return(new AppendEntryResponse()
{
ConflictName = AppendEntriesExceptionNames.ConflictingLogEntryException,
IsSuccessful = false,
ConflictingTerm = entry.PrevLogTerm,
NodeId = _nodeStorage.Id,
FirstTermIndex = 0 //always set to 0 as snapshots are assumed to be from 0 > n
});
}
}
_nodeStorage.SetCurrentTerm(entry.Term);
foreach (var log in entry.Entries)
{
var existingEnty = _nodeStorage.GetLogAtIndex(log.Index);
if (existingEnty != null && existingEnty.Term != log.Term)
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + "Found inconsistent logs in state, deleting logs from index " + log.Index);
_nodeStorage.DeleteLogsFromIndex(log.Index);
break;
}
}
NodeStateService.InCluster = true;
DateTime time = DateTime.Now;
if (entry.Entries != null && _nodeStorage.GetLogAtIndex(entry.PrevLogIndex) != null && entry.Entries.Count() > 0 && entry.Entries.First().Index > 1 && _nodeStorage.GetLogAtIndex(entry.Entries.First().Index - 1).Term != entry.PrevLogTerm)
{
Logger.LogInformation(NodeStateService.GetNodeLogId() + "Last term does not match, log " + entry.PrevLogIndex + " from term " + entry.PrevLogTerm + " does not exist.");
return(new AppendEntryResponse()
{
ConflictName = AppendEntriesExceptionNames.ConflictingLogEntryException,
IsSuccessful = false,
ConflictingTerm = entry.PrevLogTerm,
NodeId = _nodeStorage.Id,
FirstTermIndex = 0//always set to 0 as snapshots are assumed to be from 0 > n
});
}
foreach (var log in entry.Entries)
{
try
{
if (!_nodeStorage.LogExists(log.Index))
{
Logger.LogDebug(NodeStateService.GetNodeLogId() + " adding to node storage " + log);
_nodeStorage.AddLog(log);
}
}
catch (MissingLogEntryException e)
{
Logger.LogError(NodeStateService.GetNodeLogId() + " failed to add log " + log.Index + " with exception " + e.Message + Environment.NewLine + e.StackTrace);
return(new AppendEntryResponse()
{
IsSuccessful = false,
ConflictingTerm = null,
ConflictName = AppendEntriesExceptionNames.MissingLogEntryException,
FirstTermIndex = null,
NodeId = _nodeStorage.Id,
LastLogEntryIndex = _nodeStorage.GetTotalLogCount()
});
}
catch (Exception e)
{
Logger.LogError(NodeStateService.GetNodeLogId() + " failed to add log " + log.Index + " with exception " + e.Message + Environment.NewLine + e.StackTrace);
return(new AppendEntryResponse()
{
IsSuccessful = false,
ConflictingTerm = null,
ConflictName = AppendEntriesExceptionNames.LogAppendingException,
FirstTermIndex = null,
NodeId = _nodeStorage.Id,
LastLogEntryIndex = _nodeStorage.GetTotalLogCount()
});
}
}
return(new AppendEntryResponse()
{
IsSuccessful = true,
NodeId = _nodeStorage.Id,
});
}