Prevote nil if proposal is not timely (#7415)

* Prevote nil if not timely

* William's suggestion to get the proposal from the proposer instead of
generating it.

* Don't check rhs for genesis block

* Update IsTimely to match the specification

* Fix proposal tests

* Add more timely tests and check votes

* Mark proposal invalid in SetProposal, fix in the future test

* save proposal time on roundstate

* received -> receive

* always reset proposal time

* Add IsTimely test for genesis proposal

* Check timely before ValidateBlock

* Review comments from Daniel

Co-authored-by: William Banfield <wbanfield@gmail.com>

config/toml.go

@@ -572,8 +572,8 @@ var testGenesisFmt = `{
 			"time_iota_ms": "10"
 		},
 		"timing": {
-			"message_delay": "200",
-			"precision": "50"
+			"message_delay": "500000000",
+			"precision": "10000000"
 		},
 		"evidence": {
 			"max_age_num_blocks": "100000",

internal/consensus/pbts_test.go

@@ -299,7 +299,6 @@ func (p *pbtsTestHarness) run() resultSet {
 	r2 := p.height2()
 	p.intermediateHeights()
 	r5 := p.height5()
-	_ = p.observedState.Stop()
 	return resultSet{
 		genesisHeight: r1,
 		height2:       r2,
@@ -422,3 +421,75 @@ func TestProposerWaitTime(t *testing.T) {
 		})
 	}
 }
+
+func TestTimelyProposal(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	initialTime := time.Now()
+
+	cfg := pbtsTestConfiguration{
+		timingParams: types.TimingParams{
+			Precision:    10 * time.Millisecond,
+			MessageDelay: 140 * time.Millisecond,
+		},
+		timeoutPropose:             40 * time.Millisecond,
+		genesisTime:                initialTime,
+		height2ProposedBlockTime:   initialTime.Add(10 * time.Millisecond),
+		height2ProposalDeliverTime: initialTime.Add(30 * time.Millisecond),
+	}
+
+	pbtsTest := newPBTSTestHarness(ctx, t, cfg)
+	results := pbtsTest.run()
+	assert.True(t, results.height2.prevote.BlockID.Hash != nil)
+}
+
+func TestTooFarInThePastProposal(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	initialTime := time.Now()
+
+	// localtime > proposedBlockTime + MsgDelay + Precision
+	cfg := pbtsTestConfiguration{
+		timingParams: types.TimingParams{
+			Precision:    1 * time.Millisecond,
+			MessageDelay: 10 * time.Millisecond,
+		},
+		timeoutPropose:             50 * time.Millisecond,
+		genesisTime:                initialTime,
+		height2ProposedBlockTime:   initialTime.Add(10 * time.Millisecond),
+		height2ProposalDeliverTime: initialTime.Add(21 * time.Millisecond),
+	}
+
+	pbtsTest := newPBTSTestHarness(ctx, t, cfg)
+	results := pbtsTest.run()
+	time.Sleep(1 * time.Second)
+
+	assert.True(t, results.height2.prevote.BlockID.Hash == nil)
+}
+
+func TestTooFarInTheFutureProposal(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	initialTime := time.Now()
+
+	// localtime < proposedBlockTime - Precision
+	cfg := pbtsTestConfiguration{
+		timingParams: types.TimingParams{
+			Precision:    1 * time.Millisecond,
+			MessageDelay: 10 * time.Millisecond,
+		},
+		timeoutPropose:             50 * time.Millisecond,
+		genesisTime:                initialTime,
+		height2ProposedBlockTime:   initialTime.Add(100 * time.Millisecond),
+		height2ProposalDeliverTime: initialTime.Add(10 * time.Millisecond),
+		height4ProposedBlockTime:   initialTime.Add(150 * time.Millisecond),
+	}
+
+	pbtsTest := newPBTSTestHarness(ctx, t, cfg)
+	results := pbtsTest.run()
+
+	assert.True(t, results.height2.prevote.BlockID.Hash == nil)
+}

internal/consensus/state.go

@@ -754,6 +754,7 @@ func (cs *State) updateToState(ctx context.Context, state sm.State) {
 
 	cs.Validators = validators
 	cs.Proposal = nil
+	cs.ProposalReceiveTime = time.Time{}
 	cs.ProposalBlock = nil
 	cs.ProposalBlockParts = nil
 	cs.LockedRound = -1
@@ -1094,6 +1095,7 @@ func (cs *State) enterNewRound(ctx context.Context, height int64, round int32) {
 	} else {
 		logger.Debug("resetting proposal info")
 		cs.Proposal = nil
+		cs.ProposalReceiveTime = time.Time{}
 		cs.ProposalBlock = nil
 		cs.ProposalBlockParts = nil
 	}
@@ -1359,24 +1361,47 @@ func (cs *State) enterPrevote(ctx context.Context, height int64, round int32) {
 	// (so we have more time to try and collect +2/3 prevotes for a single block)
 }
 
+func (cs *State) proposalIsTimely() bool {
+	tp := types.TimingParams{
+		Precision:    cs.state.ConsensusParams.Timing.Precision,
+		MessageDelay: cs.state.ConsensusParams.Timing.MessageDelay,
+	}
+
+	return cs.Proposal.IsTimely(cs.ProposalReceiveTime, tp, cs.state.InitialHeight)
+}
+
 func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32) {
 	logger := cs.logger.With("height", height, "round", round)
 
-	// We did not receive a proposal within this round. (and thus executing this from a timeout)
+	// Check that a proposed block was not received within this round (and thus executing this from a timeout).
 	if cs.ProposalBlock == nil {
-		logger.Debug("prevote step: ProposalBlock is nil")
+		logger.Debug("prevote step: ProposalBlock is nil; prevoting nil")
 		cs.signAddVote(ctx, tmproto.PrevoteType, nil, types.PartSetHeader{})
 		return
 	}
 
-	if cs.Proposal == nil || cs.ProposalBlock == nil {
-		logger.Debug("prevote step; did not receive proposal, prevoting nil")
-		cs.signAddVote(tmproto.PrevoteType, nil, types.PartSetHeader{})
+	if cs.Proposal == nil {
+		logger.Debug("prevote step: did not receive proposal; prevoting nil")
+		cs.signAddVote(ctx, tmproto.PrevoteType, nil, types.PartSetHeader{})
 		return
 	}
 
 	if !cs.Proposal.Timestamp.Equal(cs.ProposalBlock.Header.Time) {
-		logger.Debug("proposal timestamp not equal, prevoting nil")
+		logger.Debug("prevote step: proposal timestamp not equal; prevoting nil")
+		cs.signAddVote(ctx, tmproto.PrevoteType, nil, types.PartSetHeader{})
+		return
+	}
+
+	if cs.Proposal.POLRound == -1 && cs.LockedRound == -1 && !cs.proposalIsTimely() {
+		logger.Debug("prevote step: Proposal is not timely; prevoting nil - ",
+			"proposed",
+			tmtime.Canonical(cs.Proposal.Timestamp).Format(time.RFC3339Nano),
+			"received",
+			tmtime.Canonical(cs.ProposalReceiveTime).Format(time.RFC3339Nano),
+			"msg_delay",
+			cs.state.ConsensusParams.Timing.MessageDelay,
+			"precision",
+			cs.state.ConsensusParams.Timing.Precision)
 		cs.signAddVote(ctx, tmproto.PrevoteType, nil, types.PartSetHeader{})
 		return
 	}
@@ -1385,7 +1410,7 @@ func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32
 	err := cs.blockExec.ValidateBlock(cs.state, cs.ProposalBlock)
 	if err != nil {
 		// ProposalBlock is invalid, prevote nil.
-		logger.Error("prevote step: ProposalBlock is invalid", "err", err)
+		logger.Error("prevote step: ProposalBlock is invalid; prevoting nil", "err", err)
 		cs.signAddVote(ctx, tmproto.PrevoteType, nil, types.PartSetHeader{})
 		return
 	}
@@ -1405,7 +1430,6 @@ func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32
 	*/
 	if cs.Proposal.POLRound == -1 {
 		if cs.LockedRound == -1 {
-			// TODO(@wbanfield) add check for timely here as well
 			logger.Debug("prevote step: ProposalBlock is valid and there is no locked block; prevoting the proposal")
 			cs.signAddVote(ctx, tmproto.PrevoteType, cs.ProposalBlock.Hash(), cs.ProposalBlockParts.Header())
 			return
@@ -1537,7 +1561,7 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32)
 
 	// +2/3 prevoted nil. Precommit nil.
 	if blockID.IsNil() {
-		logger.Debug("precommit step; +2/3 prevoted for nil")
+		logger.Debug("precommit step: +2/3 prevoted for nil; precommitting nil")
 		cs.signAddVote(ctx, tmproto.PrecommitType, nil, types.PartSetHeader{})
 		return
 	}
@@ -1546,24 +1570,24 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32)
 	// If we never received a proposal for this block, we must precommit nil
 	if cs.Proposal == nil || cs.ProposalBlock == nil {
 		logger.Debug("precommit step; did not receive proposal, precommitting nil")
-		cs.signAddVote(tmproto.PrecommitType, nil, types.PartSetHeader{})
+		cs.signAddVote(ctx, tmproto.PrecommitType, nil, types.PartSetHeader{})
 		return
 	}
 
 	// If the proposal time does not match the block time, precommit nil.
 	if !cs.Proposal.Timestamp.Equal(cs.ProposalBlock.Header.Time) {
-		logger.Debug("proposal timestamp not equal, precommitting nil")
+		logger.Debug("precommit step: proposal timestamp not equal; precommitting nil")
 		cs.signAddVote(ctx, tmproto.PrecommitType, nil, types.PartSetHeader{})
 		return
 	}
 
 	// If we're already locked on that block, precommit it, and update the LockedRound
 	if cs.LockedBlock.HashesTo(blockID.Hash) {
-		logger.Debug("precommit step; +2/3 prevoted locked block; relocking")
+		logger.Debug("precommit step: +2/3 prevoted locked block; relocking")
 		cs.LockedRound = round
 
 		if err := cs.eventBus.PublishEventRelock(ctx, cs.RoundStateEvent()); err != nil {
-			logger.Error("failed publishing event relock", "err", err)
+			logger.Error("precommit step: failed publishing event relock", "err", err)
 		}
 
 		cs.signAddVote(ctx, tmproto.PrecommitType, blockID.Hash, blockID.PartSetHeader)
@@ -1574,11 +1598,11 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32)
 	// the proposed block, update our locked block to this block and issue a
 	// precommit vote for it.
 	if cs.ProposalBlock.HashesTo(blockID.Hash) {
-		logger.Debug("precommit step; +2/3 prevoted proposal block; locking", "hash", blockID.Hash)
+		logger.Debug("precommit step: +2/3 prevoted proposal block; locking", "hash", blockID.Hash)
 
 		// Validate the block.
 		if err := cs.blockExec.ValidateBlock(cs.state, cs.ProposalBlock); err != nil {
-			panic(fmt.Errorf("precommit step; +2/3 prevoted for an invalid block: %w", err))
+			panic(fmt.Sprintf("precommit step: +2/3 prevoted for an invalid block %v; relocking", err))
 		}
 
 		cs.LockedRound = round
@@ -1586,7 +1610,7 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32)
 		cs.LockedBlockParts = cs.ProposalBlockParts
 
 		if err := cs.eventBus.PublishEventLock(ctx, cs.RoundStateEvent()); err != nil {
-			logger.Error("failed publishing event lock", "err", err)
+			logger.Error("precommit step: failed publishing event lock", "err", err)
 		}
 
 		cs.signAddVote(ctx, tmproto.PrecommitType, blockID.Hash, blockID.PartSetHeader)
@@ -1595,7 +1619,7 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32)
 
 	// There was a polka in this round for a block we don't have.
 	// Fetch that block, and precommit nil.
-	logger.Debug("precommit step; +2/3 prevotes for a block we do not have; voting nil", "block_id", blockID)
+	logger.Debug("precommit step: +2/3 prevotes for a block we do not have; voting nil", "block_id", blockID)
 
 	if !cs.ProposalBlockParts.HasHeader(blockID.PartSetHeader) {
 		cs.ProposalBlock = nil
@@ -1930,9 +1954,11 @@ func (cs *State) RecordMetrics(height int64, block *types.Block) {
 //-----------------------------------------------------------------------------
 
 func (cs *State) defaultSetProposal(proposal *types.Proposal) error {
+	recvTime := tmtime.Now()
+
 	// Already have one
 	// TODO: possibly catch double proposals
-	if cs.Proposal != nil {
+	if cs.Proposal != nil || proposal == nil {
 		return nil
 	}
 
@@ -1957,6 +1983,7 @@ func (cs *State) defaultSetProposal(proposal *types.Proposal) error {
 
 	proposal.Signature = p.Signature
 	cs.Proposal = proposal
+	cs.ProposalReceiveTime = recvTime
 	// We don't update cs.ProposalBlockParts if it is already set.
 	// This happens if we're already in cstypes.RoundStepCommit or if there is a valid block in the current round.
 	// TODO: We can check if Proposal is for a different block as this is a sign of misbehavior!

internal/consensus/types/round_state.go

@@ -71,14 +71,15 @@ type RoundState struct {
 	StartTime time.Time     `json:"start_time"`
 
 	// Subjective time when +2/3 precommits for Block at Round were found
-	CommitTime         time.Time           `json:"commit_time"`
-	Validators         *types.ValidatorSet `json:"validators"`
-	Proposal           *types.Proposal     `json:"proposal"`
-	ProposalBlock      *types.Block        `json:"proposal_block"`
-	ProposalBlockParts *types.PartSet      `json:"proposal_block_parts"`
-	LockedRound        int32               `json:"locked_round"`
-	LockedBlock        *types.Block        `json:"locked_block"`
-	LockedBlockParts   *types.PartSet      `json:"locked_block_parts"`
+	CommitTime          time.Time           `json:"commit_time"`
+	Validators          *types.ValidatorSet `json:"validators"`
+	Proposal            *types.Proposal     `json:"proposal"`
+	ProposalReceiveTime time.Time           `json:"proposal_receive_time"`
+	ProposalBlock       *types.Block        `json:"proposal_block"`
+	ProposalBlockParts  *types.PartSet      `json:"proposal_block_parts"`
+	LockedRound         int32               `json:"locked_round"`
+	LockedBlock         *types.Block        `json:"locked_block"`
+	LockedBlockParts    *types.PartSet      `json:"locked_block_parts"`
 
 	// Last known round with POL for non-nil valid block.
 	ValidRound int32        `json:"valid_round"`

types/params.go

@@ -129,8 +129,8 @@ func DefaultTimingParams() TimingParams {
 	// TODO(@wbanfield): Determine experimental values for these defaults
 	// https://github.com/tendermint/tendermint/issues/7202
 	return TimingParams{
-		Precision:    1 * time.Nanosecond,
-		MessageDelay: 1 * time.Nanosecond,
+		Precision:    10 * time.Millisecond,
+		MessageDelay: 500 * time.Millisecond,
 	}
 }
 

types/proposal.go

@@ -84,18 +84,24 @@ func (p *Proposal) ValidateBasic() error {
 // configured Precision and MsgDelay parameters.
 // Specifically, a proposed block timestamp is considered timely if it is satisfies the following inequalities:
 //
-// proposedBlockTime > validatorLocaltime - Precision && proposedBlockTime < validatorLocalTime + Precision + MsgDelay.
+// localtime >= proposedBlockTime - Precision
+// localtime <= proposedBlockTime + MsgDelay + Precision
 //
+// Note: If the proposal is for the `initialHeight` the second inequality is not checked. This is because
+// the timestamp in this case is set to the preconfigured genesis time.
 // For more information on the meaning of 'timely', see the proposer-based timestamp specification:
 // https://github.com/tendermint/spec/tree/master/spec/consensus/proposer-based-timestamp
-func (p *Proposal) IsTimely(clock tmtime.Source, tp TimingParams) bool {
-	lt := clock.Now()
-	lhs := lt.Add(-tp.Precision)
-	rhs := lt.Add(tp.Precision).Add(tp.MessageDelay)
-	if lhs.Before(p.Timestamp) && rhs.After(p.Timestamp) {
-		return true
+func (p *Proposal) IsTimely(recvTime time.Time, tp TimingParams, initialHeight int64) bool {
+	// lhs is `proposedBlockTime - Precision` in the first inequality
+	lhs := p.Timestamp.Add(-tp.Precision)
+	// rhs is `proposedBlockTime + MsgDelay + Precision` in the second inequality
+	rhs := p.Timestamp.Add(tp.MessageDelay).Add(tp.Precision)
+
+	if recvTime.Before(lhs) || (p.Height != initialHeight && recvTime.After(rhs)) {
+		return false
 	}
-	return false
+
+	return true
 }
 
 // String returns a string representation of the Proposal.

types/proposal_test.go

@@ -14,7 +14,6 @@ import (
 	"github.com/tendermint/tendermint/internal/libs/protoio"
 	tmrand "github.com/tendermint/tendermint/libs/rand"
 	tmtime "github.com/tendermint/tendermint/libs/time"
-	tmtimemocks "github.com/tendermint/tendermint/libs/time/mocks"
 	tmproto "github.com/tendermint/tendermint/proto/tendermint/types"
 )
 
@@ -217,47 +216,84 @@ func TestIsTimely(t *testing.T) {
 	genesisTime, err := time.Parse(time.RFC3339, "2019-03-13T23:00:00Z")
 	require.NoError(t, err)
 	testCases := []struct {
-		name         string
-		proposalTime time.Time
-		localTime    time.Time
-		precision    time.Duration
-		msgDelay     time.Duration
-		expectTimely bool
+		name           string
+		genesisHeight  int64
+		proposalHeight int64
+		proposalTime   time.Time
+		recvTime       time.Time
+		precision      time.Duration
+		msgDelay       time.Duration
+		expectTimely   bool
 	}{
+		// proposalTime - precision <= localTime <= proposalTime + msgDelay + precision
 		{
 			// Checking that the following inequality evaluates to true:
-			// 1 - 2 < 0 < 1 + 2 + 1
-			name:         "basic timely",
-			proposalTime: genesisTime,
-			localTime:    genesisTime.Add(1 * time.Nanosecond),
-			precision:    time.Nanosecond * 2,
-			msgDelay:     time.Nanosecond,
-			expectTimely: true,
+			// 0 - 2 <= 1 <= 0 + 1 + 2
+			name:           "basic timely",
+			genesisHeight:  1,
+			proposalHeight: 2,
+			proposalTime:   genesisTime,
+			recvTime:       genesisTime.Add(1 * time.Nanosecond),
+			precision:      time.Nanosecond * 2,
+			msgDelay:       time.Nanosecond,
+			expectTimely:   true,
 		},
 		{
 			// Checking that the following inequality evaluates to false:
-			// 3 - 2 < 0 < 3 + 2 + 1
-			name:         "local time too large",
-			proposalTime: genesisTime,
-			localTime:    genesisTime.Add(3 * time.Nanosecond),
-			precision:    time.Nanosecond * 2,
-			msgDelay:     time.Nanosecond,
-			expectTimely: false,
+			// 0 - 2 <= 4 <= 0 + 1 + 2
+			name:           "local time too large",
+			genesisHeight:  1,
+			proposalHeight: 2,
+			proposalTime:   genesisTime,
+			recvTime:       genesisTime.Add(4 * time.Nanosecond),
+			precision:      time.Nanosecond * 2,
+			msgDelay:       time.Nanosecond,
+			expectTimely:   false,
 		},
 		{
 			// Checking that the following inequality evaluates to false:
-			// 0 - 2 < 2 < 2 + 1
-			name:         "proposal time too large",
-			proposalTime: genesisTime.Add(4 * time.Nanosecond),
-			localTime:    genesisTime,
-			precision:    time.Nanosecond * 2,
-			msgDelay:     time.Nanosecond,
-			expectTimely: false,
+			// 4 - 2 <= 0 <= 4 + 2 + 1
+			name:           "proposal time too large",
+			genesisHeight:  1,
+			proposalHeight: 2,
+			proposalTime:   genesisTime.Add(4 * time.Nanosecond),
+			recvTime:       genesisTime,
+			precision:      time.Nanosecond * 2,
+			msgDelay:       time.Nanosecond,
+			expectTimely:   false,
+		},
+		{
+			// Checking that the following inequality evaluates to true:
+			// 0 - 2 <= 4
+			// and the following check is skipped
+			// 4 <= 0 + 1 + 2
+			name:           "local time too large but proposal is for genesis",
+			genesisHeight:  1,
+			proposalHeight: 1,
+			proposalTime:   genesisTime,
+			recvTime:       genesisTime.Add(4 * time.Nanosecond),
+			precision:      time.Nanosecond * 2,
+			msgDelay:       time.Nanosecond,
+			expectTimely:   true,
+		},
+		{
+			// Checking that the following inequality evaluates to false:
+			// 4 - 2 <= 0
+			name:           "proposal time too large for genesis block proposal",
+			genesisHeight:  1,
+			proposalHeight: 1,
+			proposalTime:   genesisTime.Add(4 * time.Nanosecond),
+			recvTime:       genesisTime,
+			precision:      time.Nanosecond * 2,
+			msgDelay:       time.Nanosecond,
+			expectTimely:   false,
 		},
 	}
+
 	for _, testCase := range testCases {
 		t.Run(testCase.name, func(t *testing.T) {
 			p := Proposal{
+				Height:    testCase.proposalHeight,
 				Timestamp: testCase.proposalTime,
 			}
 
@@ -266,10 +302,7 @@ func TestIsTimely(t *testing.T) {
 				MessageDelay: testCase.msgDelay,
 			}
 
-			mockSource := new(tmtimemocks.Source)
-			mockSource.On("Now").Return(testCase.localTime)
-
-			ti := p.IsTimely(mockSource, tp)
+			ti := p.IsTimely(testCase.recvTime, tp, testCase.genesisHeight)
 			assert.Equal(t, testCase.expectTimely, ti)
 		})
 	}