Network fails to generate new block: RAFT consensus error

[subhodi]

System information

Geth version: geth version
Geth/v1.7.2-stable-0905eda4/linux-amd64/go1.7.3
RAFT consensus

OS & Version: Windows/Linux/OSX
Ubuntu 16.04

Branch, Commit Hash or Release: git status
Tag: v2.0.0

Expected behaviour

On receiving new transactions network should create a new block.

Actual behaviour

network fails to generate new blocks. Nodes run into the infinite loop on RAFT consensus.

Steps to reproduce the behaviour

1. 3 node setup on individual machines.
2. Deploy single contract with mapping(uint => uint).
3. Write 10M(key-value pairs) entries to the contract
4. While populating these key-values network consensus fails and Resource utilization of each node becomes CPU: 99%, RAM: 99%.

Backtrace

Initial log

Someone else mined invalid block; ignoring block=0538ab…7e291f
INFO [03-19|07:23:48] Non-extending block                      block=600f65…c0ba5d                                                    parent=0538ab…7e291f head=d00c48…3933a2
INFO [03-19|07:23:48] persisted the latest applied index       index=764
INFO [03-19|07:23:48] Handling InvalidRaftOrdering             invalid block=600f65…c0ba5d current head=d00c48…3933a2
INFO [03-19|07:23:48] Non-extending block                      block=620b4a…d9f350                                                    parent=600f65…c0ba5d head=d00c48…3933a2
INFO [03-19|07:23:48] persisted the latest applied index       index=765
INFO [03-19|07:23:48] Someone else mined invalid block; ignoring block=600f65…c0ba5d
INFO [03-19|07:23:48] Handling InvalidRaftOrdering             invalid block=620b4a…d9f350 current head=d00c48…3933a2
INFO [03-19|07:23:48] Someone else mined invalid block; ignoring block=620b4a…d9f350
raft2018/03/19 07:23:48 INFO: raft.node: 1 elected leader 3 at term 31

Then each node logs

raft2018/03/19 07:29:37 INFO: 1 became follower at term 219
raft2018/03/19 07:29:37 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 219
raft2018/03/19 07:29:38 INFO: 1 [term: 219] received a MsgVote message with higher term from 2 [term: 220]
raft2018/03/19 07:29:38 INFO: 1 became follower at term 220
raft2018/03/19 07:29:38 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 220
raft2018/03/19 07:29:40 INFO: 1 [term: 220] received a MsgVote message with higher term from 2 [term: 221]
raft2018/03/19 07:29:40 INFO: 1 became follower at term 221
raft2018/03/19 07:29:40 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 221
raft2018/03/19 07:29:42 INFO: 1 [term: 221] received a MsgVote message with higher term from 2 [term: 222]
raft2018/03/19 07:29:42 INFO: 1 became follower at term 222
raft2018/03/19 07:29:42 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 222
2018-03-19 07:29:43.726388 W | rafthttp: the clock difference against peer 3 is too high [18.266505003s > 1s]
2018-03-19 07:29:43.726438 W | rafthttp: the clock difference against peer 2 is too high [1.472092164s > 1s]
raft2018/03/19 07:29:44 INFO: 1 [term: 222] received a MsgVote message with higher term from 2 [term: 223]
raft2018/03/19 07:29:44 INFO: 1 became follower at term 223
raft2018/03/19 07:29:44 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 223
raft2018/03/19 07:29:45 INFO: 1 [term: 223] received a MsgVote message with higher term from 2 [term: 224]
raft2018/03/19 07:29:45 INFO: 1 became follower at term 224
raft2018/03/19 07:29:45 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 224
raft2018/03/19 07:29:46 INFO: 1 [term: 224] received a MsgVote message with higher term from 2 [term: 225]
raft2018/03/19 07:29:46 INFO: 1 became follower at term 225
raft2018/03/19 07:29:46 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 225
raft2018/03/19 07:29:48 INFO: 1 [term: 225] received a MsgVote message with higher term from 2 [term: 226]
raft2018/03/19 07:29:48 INFO: 1 became follower at term 226
raft2018/03/19 07:29:48 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 226
raft2018/03/19 07:29:49 INFO: 1 [term: 226] received a MsgVote message with higher term from 2 [term: 227]
raft2018/03/19 07:29:49 INFO: 1 became follower at term 227
raft2018/03/19 07:29:49 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 227
raft2018/03/19 07:29:50 INFO: 1 [term: 227] received a MsgVote message with higher term from 2 [term: 228]
raft2018/03/19 07:29:50 INFO: 1 became follower at term 228
raft2018/03/19 07:29:50 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 228
raft2018/03/19 07:29:51 INFO: 1 [term: 228] received a MsgVote message with higher term from 2 [term: 229]
raft2018/03/19 07:29:51 INFO: 1 became follower at term 229
raft2018/03/19 07:29:51 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 229
raft2018/03/19 07:29:53 INFO: 1 [term: 229] received a MsgVote message with higher term from 2 [term: 230]
raft2018/03/19 07:29:53 INFO: 1 became follower at term 230
raft2018/03/19 07:29:53 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 230
raft2018/03/19 07:29:54 INFO: 1 [term: 230] received a MsgVote message with higher term from 2 [term: 231]
raft2018/03/19 07:29:54 INFO: 1 became follower at term 231
raft2018/03/19 07:29:54 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 231
raft2018/03/19 07:29:55 INFO: 1 [term: 231] received a MsgVote message with higher term from 2 [term: 232]
raft2018/03/19 07:29:55 INFO: 1 became follower at term 232
raft2018/03/19 07:29:55 INFO: 1 [logterm: 51, index: 771, vote: 0] rejected MsgVote from 2 [logterm: 51, index: 769] at term 232
raft2018/03/19 07:29:56 INFO: 1 [term: 232] received a MsgVote message with higher term from 2 [term: 233]

[jpmsam]

@subhodi Would you be able to share the scripts/contracts that you used?

[subhodi]

@jpmsam
contract : https://gist.github.com/subhodi/5ac59d371c2e6993cffd36b237ac4e21
And using web3, execute seedMap method seed the contract state with 10M entries.

[antonmok]

There is some info
etcd-io/etcd#8553

[jpmsam]

@subhodi would you be able to confirm if PR resolves this issue for you?

[subhodi]

@jpmsam Sure, but i need some time to setup and re-run everything.

[fixanoid]

Please reopen if this is still an issue. Thanks!