fix(consensus): proposal not generated after waiting for last block t…

…ime to pass (#849)

* test(consensus): test that genesis time is set correctly

* fix(consensus): proposal not generated after waiting for last block time to pass

internal/consensus/state.go

@@ -746,7 +746,7 @@ func (cs *State) handleTimeout(
 		// XXX: should we fire timeout here (for timeout commit)?
 		_ = cs.ctrl.Dispatch(ctx, &EnterNewRoundEvent{Height: ti.Height}, stateData)
 	case cstypes.RoundStepNewRound:
-		_ = cs.ctrl.Dispatch(ctx, &EnterProposeEvent{Height: ti.Height}, stateData)
+		_ = cs.ctrl.Dispatch(ctx, &EnterProposeEvent{Height: ti.Height, Round: ti.Round}, stateData)
 	case cstypes.RoundStepPropose:
 		if err := cs.eventBus.PublishEventTimeoutPropose(stateData.RoundStateEvent()); err != nil {
 			cs.logger.Error("failed publishing timeout propose", "err", err)
@@ -788,7 +788,7 @@ func (cs *State) handleTxsAvailable(ctx context.Context, stateData *StateData) {
 		cs.roundScheduler.ScheduleTimeout(timeoutCommit, stateData.Height, 0, cstypes.RoundStepNewRound)
 
 	case cstypes.RoundStepNewRound: // after timeoutCommit
-		_ = cs.ctrl.Dispatch(ctx, &EnterProposeEvent{Height: stateData.Height}, stateData)
+		_ = cs.ctrl.Dispatch(ctx, &EnterProposeEvent{Height: stateData.Height, Round: stateData.Round}, stateData)
 	}
 }
 

internal/consensus/state_test.go

@@ -361,6 +361,74 @@ func TestStateProposalTime(t *testing.T) {
 	}
 }
 
+// TestStateLastBlockTimeInFuture ensures that whenever the last block time is in the future at genesis,
+// the node waits before generating proposal.
+func TestStateLastBlockTimeInFuture(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	logger := log.NewTestingLoggerWithLevel(t, log.LogLevelTrace)
+
+	config := configSetup(t)
+
+	app, err := kvstore.NewMemoryApp(kvstore.WithDuplicateRequestDetection(false))
+	require.NoError(t, err)
+	cs1, _ := makeState(ctx, t, makeStateArgs{config: config, validators: 1, application: app, logger: logger})
+	ctx = dash.ContextWithProTxHash(ctx, cs1.privValidator.ProTxHash)
+	stateData := cs1.GetStateData()
+	height, round := stateData.Height, stateData.Round
+	cs1.config.DontAutoPropose = true
+	cs1.config.CreateEmptyBlocksInterval = 0
+	stateData.state.ConsensusParams.Synchrony.MessageDelay = 5 * time.Millisecond
+	stateData.state.ConsensusParams.Synchrony.Precision = 10 * time.Millisecond
+	delay := stateData.state.ConsensusParams.Synchrony.MessageDelay
+	precision := stateData.state.ConsensusParams.Synchrony.Precision
+
+	// set genesis time (==last block time at height 0) in the future
+	assert.Equal(t, int64(1), height, "we should be on genesis")
+	genesisTime := tmtime.Now().Add(delay + precision + 10*time.Millisecond)
+	stateData.state.LastBlockTime = genesisTime
+	err = stateData.Save()
+	require.NoError(t, err)
+
+	newRoundCh := subscribe(ctx, t, cs1.eventBus, types.EventQueryNewRound)
+
+	startTestRound(ctx, cs1, height, round)
+
+	// Wait for new round so proposer is set.
+	ensureNewRound(t, newRoundCh, height, round)
+
+	stateData = cs1.GetStateData()
+	height, round = stateData.Height, stateData.Round
+	cs := cs1
+	// Generate proposal block
+	propBlock, err := cs.CreateProposalBlock(ctx)
+	require.NoError(t, err)
+
+	parSet, err := propBlock.MakePartSet(types.BlockPartSizeBytes)
+	require.NoError(t, err)
+	stateData.ValidBlock = propBlock
+	stateData.ValidBlockParts = parSet
+
+	// Wait for complete proposal.
+	err = cs.ctrl.Dispatch(ctx, &EnterProposeEvent{
+		Height: height,
+		Round:  round,
+	}, &stateData)
+	require.NoError(t, err)
+
+	time.Sleep(delay + precision + 100*time.Millisecond)
+	ensureNewRound(t, newRoundCh, height+1, 0)
+
+	stateData = cs.GetStateData()
+
+	assert.Greater(t, stateData.Height, int64(1), "we should have at least one block")
+	block1 := cs.blockStore.LoadBlock(1)
+	require.NotNil(t, block1)
+
+	assert.Equal(t, genesisTime, block1.Time, "expected that last block time is in the past")
+}
+
 func TestStateOversizedBlock(t *testing.T) {
 	config := configSetup(t)
 	ctx, cancel := context.WithCancel(context.Background())

internal/consensus/ticker.go

@@ -115,9 +115,9 @@ func (t *timeoutTicker) timeoutRoutine(ctx context.Context) {
 			// NOTE time.Timer allows duration to be non-positive
 			ti = newti
 			t.timer.Reset(ti.Duration)
-			t.logger.Trace("Internal state machine timeout scheduled", "duration", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step.String())
+			t.logger.Trace("Internal state machine timeout scheduled", "duration", ti.Duration.String(), "height", ti.Height, "round", ti.Round, "step", ti.Step.String())
 		case <-t.timer.C:
-			t.logger.Debug("Internal state machine timeout elapsed", "duration", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step.String())
+			t.logger.Debug("Internal state machine timeout elapsed", "duration", ti.Duration.String(), "height", ti.Height, "round", ti.Round, "step", ti.Step.String())
 			// go routine here guarantees timeoutRoutine doesn't block.
 			// Determinism comes from playback in the receiveRoutine.
 			// We can eliminate it by merging the timeoutRoutine into receiveRoutine