Consensus stuck in votesync upon restart

[aditiharini]

On restarts where the proposer has to restream a precommited value (i.e. hitsRestreamValue) consensus halts in votesync.

The non-proposing nodes don't have the precommit votes for the restreamed value though the value has a pol round on it. The proposing node, never gets votes from its peers and gets stuck in votesync indefinitely.

Logs attached:

node1-shard8.txt

node2-shard8.txt

node3-shard8.txt

[ancazamfir]

Thanks @aditiharini for the issue.

Looked at the logs and here is a preliminary analysis
Looks like nodes restart, with last decided height 3290 and they move to height 3291, round 0
There are two values that show up:

• v1 = 2e32197974e8513749480d257026d4806465b4167ea50b841f5b2abd2aa2f76f
• v2 = 02879ba954a442c6f60ed9f4061c938396068ce65f7ba09268fea685a91ad761
  They are being proposed for the same height and round by Node 2 so we deal with a byzantine proposer.
  We are also not handling correctly equivocation, causing Node 1 to lock on v1 which breaks consensus.

Node 1:

• id = 51141fcc0a9b6d81f5702a12150e066c9e2998100aedf250703ccac6cbfac22b
• proposer at (3291, 2)
• 0 WAL entries
• receives proposal for v2 from Node 2
• votes for v2
• receives vote for v2 from Node 2
• receives vote for v2 from Node 3 => ProposalAndPolkaCurrent
  - locks on v2

Node 2:

• id = 75d3277a1b4bb12f9ccd873a4792a8a50c65b91e44edd069e189428fe1c90052
• proposer at (3291, 0)
• replays 3 WAL entries:
  • replays its proposal for v1
  • replays its prevote for v1
  • replays prevote for v1 from Node 3
• proposes v2, a different value for same height and round
• votes for v2 => goes out but dropped internally, considered equivocation
• receives prevote for v2 from Node 1 => PolkaAny
• receives prevote for v2 from Node 3, discards it

Node 3:

• id = 3ba482c21b98a3fb18f1463699ca4045e00d44ec00b1043285f46f2e4caa10b5
• proposer at (3291, 1)
• replays 3 WAL entries:
  • replays proposal for v1 from Node 2, stores as it is incomplete
  • replays its prevote for v1
  • replays prevote for v1 from Node 2
• receives v2
• votes for v2 => goes out but dropped internally, considered equivocation
• receives prevote for v2 from Node 2, discards
• receives prevote for v2 from Node 3 => PolkaAny

So there are a couple of things that we need to fix:

• the application should not propose different value after restart
  • could you check the snapchain code for this?
• consensus should not broadcast votes if it already has voted for the same height and round with different value - we will fix this as part of this issue

[aditiharini]

There is another case where consensus halts even though the proposed values are consistent across restart. Here, it seems like there is some issue with lost/missing votes. I've attached the logs.

node1-shard8.txt
node2-shard8.txt
node3-shard8.txt

[ancazamfir]

thanks @aditiharini for the new logs!
So, besides the issue above:

consensus should not broadcast votes if it already has voted for the same height and round with different value

there are two more problems (see notes for Node 3):

• Votes may be processed before WAL replay
• When a Proposal(h, r, v, vr) is received without a PolkaPrevious, consensus cancels the propose timeout therefore never reaching the Prevote step and starting vote sync. It would not have helped in this case but we need to fix this.

See more in the notes below and also the snapshot of votes and proposals at each round.

Node 1:

• id = 51141fcc0a9b6d81f5702a12150e066c9e2998100aedf250703ccac6cbfac22b
• proposer at (109, 1)
• 5 WAL entries
  • replays Proposal(109, 0, v1, -1), stores it, no full value
  • replays (own) Prevote(109, 0, v1) from Node 1
  • replays Prevote(109, 0, v1) from Node 3
  • replays Prevote(109, 0, v1) from Node 2 => PolkaAny
  • replays (own) Precommit(109, 0, v1) from Node 1
• timeouts on Propose step, moves to Prevote
• sends Prevote(109, 0, nil) -> this is dropped internally but it goes out and it shouldn't
• PolkaAny - starts prevote timer
• prevote timer expires -> step Precommit
• sends Precommit(109, 0, nil)-> this is dropped internally but it goes out and it shouldn't
• receives full value for v1
• receives Prevote(109, 0, v1), Node 2
• receives Precommit(109, 0, v1), Node 2
• receives full proposal for v1 from Node 3 => ProposalAndPolkaCurrent, no messasge ( L36, L42 - sets valid but not locked - correct)
• receives Prevote(109, 0, v1) from Node 3
• a second later receives Precommit(109, 0, nil) from Node 3
  => precommitAny, starts precommit timer
• timer elapses, moves to round 1
• proposes via L16 (valid_round=0)
• runs L28 and sends Proposal(109, 1, v1, 0)
• receives Prevote(109, 1, v1), Node 2
• stuck in prevote, vote sync receives the same two votes

Proposals and votes for round 0:

  Proposal(109, 0, v1, -1), Node 3
  Prevote(109, 0, v1), Node 1
  Prevote(109, 0, v1), Node 2
  Prevote(109, 0, v1), Node 3
  Precommit(109, 0, v1), Node 1
  Precommit(109, 0, v1), Node 2
  Precommit(109, 0, nil), Node 3

Proposals and votes for round 1:

  Proposal(109, 1, v1, 0), Node 1
  Prevote(109, 1, v1), Node 1
  Prevote(109, 1, v1), Node 2

Node 2:

• id = 75d3277a1b4bb12f9ccd873a4792a8a50c65b91e44edd069e189428fe1c90052
• replays 6 WAL entries:
  • replays Proposal(109, 0, v1, -1), stores it, no full value
  • replays (own) Prevote(109, 0, v1) from Node 2
  • replays Prevote(109, 0, v1) from Node 3
  • replays Prevote(109, 0, v1) from Node 1 => PolkaAny
  • replays (own) Precommit(109, 0, v1) from Node 2
  • replays Precommit(109, 0, v1) from Node 3
• receives Prevote(109, 0, nil) from Node 1 (drops)
• receives Precommit(109, 0, nil) from Node 1 => Precommit Any
• starts timeout precommit (still in Propose step)
• receives full value for v1 from Node 3
• sends Prevote(109, 0, v1)
• sends Precommit(109, 0, v1), moves to Precommit, starts timeout
• receives full proposal for v1 from Node 3
• receives Prevote(109, 0, v1) from Node 3
• precommit timer expires, moves to round 1
• receives Precommit(109, 0, nil), Node 3 (drops)
• receives Prevote(109, 1, v1), Node 1
• receives Proposal(109, 1, v1, 0), Node 1
• sends Prevote(109, 1, v1), Node 2
• stuck in prevote, vote sync receives the same two votes

Proposals and votes for round 0:

  Proposal(109, 0, v1, -1), Node 3
  Prevote(109, 0, v1), Node 1
  Prevote(109, 0, v1), Node 2
  Prevote(109, 0, v1), Node 3
  Precommit(109, 0, v1), Node 2
  Precommit(109, 0, v1), Node 3
  Precommit(109, 0, nil), Node 1

Proposals and votes for round 1:

  Proposal(109, 1, v1, 0), Node 1
  Prevote(109, 1, v1), Node 1
  Prevote(109, 1, v1), Node 2

Node 3:

• id = 3ba482c21b98a3fb18f1463699ca4045e00d44ec00b1043285f46f2e4caa10b5
• proposer at (109,0)
• receives Prevote(109, 0, nil) from Node 1 (processed before WAL replay)
• replays 6 WAL entries:
  • replays Proposal(109, 0, v1, -1), stores it, no full value
  • replays (own) Prevote(109, 0, v1) from Node 3
  • replays Prevote(109, 0, v1) from Node 1 (dropped)
  • replays Prevote(109, 0, v1) from Node 2 => PolkaAny
  • replays (own) Precommit(109, 0, v1) from Node 3
  • replays Precommit(109, 0, v1) from Node 2
• reproposes v1 => PolkaAny (due to prevote(nil) from Node 1 earlier
• sends Prevote(109, 0, v1), Node 3
• starts prevote timer
• receives Precommit(109, 0, nil) from Node 1 => PrecommitAny
• starts precommit timer
• receives Prevote(109, 0, v1) from Node 2
• receives Precommit(109, 0, v1) from Node 2
• timeout Precommit
• sends Precommit(109, 0, nil), moves to round 1, it should not
• receives Proposal(v1, vr=0) from Node 1 -> drops it, remains in Propose step but cancels the timer, therefore it never runs Vote Sync

Proposals and votes for round 0:

  Proposal(109, 0, v1, -1), Node 3
  Prevote(109, 0, nil), Node 1
  Prevote(109, 0, v1), Node 2
  Prevote(109, 0, v1), Node 3
  Precommit(109, 0, v1), Node 2
  Precommit(109, 0, v1), Node 3
  Precommit(109, 0, nil), Node 1

Proposals and votes for round 1:

  Proposal(109, 1, v1, 0), Node 1
  Prevote(109, 1, v1), Node 1
  Prevote(109, 1, v1), Node 2

[ancazamfir]

@cason @josef-widder @romac - this is related to our discussion about votesync and PolkaCertificate. Our bugs in consensus simulate the byzantine validator that sends different votes to different nodes and in this particular case sending the PolkaCertificate for (109, 0, v1) would have helped to unstuck round 1 via L28.

[nenadmilosevic95]

Hey @ancazamfir, in the description of the first problem scenario, is this a typo in the Node 3 section:

• receives prevote for v2 from Node 3 => PolkaAny

Is it from Node 3 or from Node 1?

[ancazamfir]

Is it from Node 3 or from Node 1?

Sorry about that, it's from Node 1. Good catch!

[nenadmilosevic95]

Thanks @ancazamfir ! And the scenario you described is round 0? Do they halt in this round? I understand that already from your description we can see these wrong behaviors you have highlighted but I would like to understand the whole execution so we are sure we are not missing some other faulty behaviors.

[ancazamfir]

Thanks @ancazamfir ! And the scenario you described is round 0? Do they halt in this round? I understand that already from your description we can see these wrong behaviors you have highlighted but I would like to understand the whole execution so we are sure we are not missing some other faulty behaviors.

The first scenario described (for height 3291) is for round 0. Consensus is stuck later (in round 2). Briefly what happens:

• All move to round 1 due to prevote and precommit timeouts, timers started by PolkaAny and PrecommityAny repectively.
• Node 3, proposer of round 1, proposes some v3 on which Node1 prevotes nil (as it is locked on v2)
• Again all nodes move to round 2 due to prevote and precommit timeouts
• Node 1, proposer of round 2, reproposes v2 but Node 2 and Node 3 reject the (re)proposal as they don't have the PolkaPrevious (they cannot run L28)
• Now we run in the other bug I mentioned:

When a Proposal(h, r, v, vr) is received without a PolkaPrevious, consensus cancels the propose timeout therefore never reaching the Prevote step and starting vote sync. It would not have helped in this case but we need to fix this.

Due to this Node 2 and Node 3 stay suck in Propose step because (with the bug) the Propose timeout has been canceled. But note that even without the bug, Node 2 and Node 3 would have timed out the Proposal, prevote nil, then precommit nil, move to next round and the cycles repeats.

So to summarize:

• with the tested version, consensus is stuck at round 2 due to bad handling of L28: Proposal without PolkaPrevious
• without this bug we would have gone on multiple rounds forever
• the root cause is the vote equivocation

If things are not clear I can update first scenario (height 3291) with more details for rounds 1 and 2.

[nenadmilosevic95]

Thanks @ancazamfir, you don't need to update it, it is super clear now!

Just to summarize everything:

1. vote equivocation after restart (fix in PR fix(code/core-consensus): Prevent nodes from broadcasting equivocating votes #864 )
2. proposal equivocation after restart (is fix in PR fix(code/core-consensus): Reproduce and fix consensus being stuck with byzantine proposer #853 for this? )
3. cancelling of timeoutPropose and not entering prevote step (fix in PR fix(code/core-consensus): Only cancel propose timeout on a step change #862 )

And lastly, although in this setup Tendermint does not guarantee to tolerate any Byzantine behavior since we have 3 nodes only, in general we should be able to tolerate equivocation. Namely we need to allow an honest node to learn equivocated votes and proposals to ensure liveness. Is this issue about this - #857?