Raft got into state where it repeatedly messaged that last index is greater

[keyneston]

After frequent restart (while testing an init script) I somehow managed to get consul/raft into a state where it rejected all messages. I attempted to set -log-level {debug,trace} but the only thing it would print is:

consul:     2014/04/22 21:58:11 [WARN] raft: Rejecting vote since our last index is greater

Deleting the -data-dir fixed the local issue.

[armon]

Could you give some more details? Particularly, how many server nodes were there? Was the bootstrap flag being used?
More log output would also be useful.

This message basically translates to "another node is asking to be elected, but the local node has more recent data, rejecting the vote". It means this node is just refusing to vote for another node. In most cases, this is not a bug, just an informative message.

[keyneston]

Currently there are three nodes in the cluster.

It appears I just missed the relevant log lines on the first pass: https://gist.github.com/Tarrant/11203470

Hope this helps!
-T

[keyneston]

The consul logs form the run just prior to it freaking out: https://gist.github.com/Tarrant/11203507

[armon]

@tarrant Hmm. It is hard to tell exactly what is happening from the logs. If you can reproduce this the output of consul info would be useful, as well as the logs of the other servers. As far as I can tell, Raft does seem to be working as intended. The node seems to have been the leader previously and had a bunch of pending writes, so it's log is longer, and it is reject votes for other nodes. The ODD part is that this node is not entering the candidate state, or that the other two nodes are not able to win either. Do you have their logs?

[keyneston]

I only have logs for one of the two other boxes:

https://gist.github.com/Tarrant/11203470#file-reltool2-log

[armon]

Now I'm super confused haha. Seems that BOTH reltool1 and reltool2 believe their log to be ahead, and yet neither of them is willing to become a candidate. Are all 3 running the same binary? We've changed some of the timing values around since 0.1 was released, and its possible reltool1 and reltool2 will never enter the candidate state since franken8 is always pre-empting them to the election.

[armon]

@tarrant I just pushed some changes to Raft to provide more debugging info for this as well: hashicorp/raft@a98ae57

[keyneston]

No, I believe franken8 is running an old version as I'm just automating the rollout. I'll package a98ae57c589de765a7004ac222b1a3d31f2e46d5 and try and replicate in the morning.

[keyneston]

I just managed to reproduce this. I'm using consul commit b8d185a and raft commit hashicorp/raft@a98ae57

Logs: https://gist.github.com/tarrant/11233608

I tried restarting reltool1 many times to replicate the error. Then I gave up on that. I then went and termed franken8 since it was the leader in an attempt to shift leadership over to reltool1.

[armon]

@tarrant Nice! I think I know what the issue is now. Basically Raft has an ElectionTimeout and a HeartbeatTimeout value. If we don't hear from the leader in HeartbeatTimeout we start an election. We restart the election every ElectionTimeout until eventually somebody ones. In this case ElectionTimeout is 400ms and HeartbeatTimeout 1s.

Due to the safety properties of Raft, franken8 can never win since it is behind, hence the message about rejecting the vote. But because of these values, if franken8 reaches the HeartbeatTimeout first, it will run the election first. It will loose, but it will restart the election every 400ms. This pre-empts the other two nodes (which could win) since they will only timeout every 1s.

I think the solution to this is actually to ensure ElectionTimeout >= HeartbeatTimeout. Let me push the appropriate changes now.

[armon]

Also looks like you really are torturing Consul in these logs!

[armon]

@tarrant I just pushed hashicorp/raft@09d87a3. I am fairly confident this was the root of the issue. This was easier to trigger before since the old node has a HeartbeatTimeout of 300ms, instead of 1s in the latest versions. I think the ElectionTimeout was the lurking issue in there, which should be resolved now. Let me know if you can reproduce it, otherwise we can close the ticket.

Thanks a lot for beating on this!

[keyneston]

Sweet! Thanks for the update, I'll test it in the morning but I doubt I'll be able to definitively prove anything since I'm still not 100% sure how I got it into the state. If you don't object I think we should close the ticket and then reopen if it reoccurs?

Thanks for the project I'm having a lot of fun exploring it.

[armon]

Sounds good. I think we've got this one nailed down now.