diff --git a/config/toml.go b/config/toml.go index abdf9bf5d..0fe427053 100644 --- a/config/toml.go +++ b/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", diff --git a/internal/consensus/pbts_test.go b/internal/consensus/pbts_test.go index 05888b62a..82f5d18e6 100644 --- a/internal/consensus/pbts_test.go +++ b/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) +} diff --git a/internal/consensus/state.go b/internal/consensus/state.go index eb6582935..06d442f09 100644 --- a/internal/consensus/state.go +++ b/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! diff --git a/internal/consensus/types/round_state.go b/internal/consensus/types/round_state.go index 9e67b76c0..190f8576f 100644 --- a/internal/consensus/types/round_state.go +++ b/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"` diff --git a/types/params.go b/types/params.go index 255181415..90f29e66a 100644 --- a/types/params.go +++ b/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, } } diff --git a/types/proposal.go b/types/proposal.go index 8daccdd82..31336dab7 100644 --- a/types/proposal.go +++ b/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. diff --git a/types/proposal_test.go b/types/proposal_test.go index 136e8a8e3..c5a30a15a 100644 --- a/types/proposal_test.go +++ b/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) }) }