Improve logging of unexpected proposer errors (#2646)

snow/engine/snowman/transitive.go

@@ -1121,12 +1121,14 @@ func (t *Transitive) addUnverifiedBlockToConsensus(
 	issuedMetric prometheus.Counter,
 ) (bool, error) {
 	blkID := blk.ID()
+	blkHeight := blk.Height()
 
 	// make sure this block is valid
 	if err := blk.Verify(ctx); err != nil {
 		t.Ctx.Log.Debug("block verification failed",
 			zap.Stringer("nodeID", nodeID),
 			zap.Stringer("blkID", blkID),
+			zap.Uint64("height", blkHeight),
 			zap.Error(err),
 		)
 
@@ -1143,6 +1145,7 @@ func (t *Transitive) addUnverifiedBlockToConsensus(
 	t.Ctx.Log.Verbo("adding block to consensus",
 		zap.Stringer("nodeID", nodeID),
 		zap.Stringer("blkID", blkID),
+		zap.Uint64("height", blkHeight),
 	)
 	return true, t.Consensus.Add(ctx, &memoryBlock{
 		Block:   blk,

vms/proposervm/block.go

@@ -349,7 +349,7 @@ func (p *postForkCommonComponents) verifyPreDurangoBlockDelay(
 
 	delay := blkTimestamp.Sub(parentTimestamp)
 	if delay < minDelay {
-		return false, errProposerWindowNotStarted
+		return false, fmt.Errorf("%w: delay %s < minDelay %s", errProposerWindowNotStarted, delay, minDelay)
 	}
 
 	return delay < proposer.MaxVerifyDelay, nil
@@ -364,14 +364,15 @@ func (p *postForkCommonComponents) verifyPostDurangoBlockDelay(
 	var (
 		blkTimestamp = blk.Timestamp()
 		blkHeight    = blk.Height()
+		currentSlot  = proposer.TimeToSlot(parentTimestamp, blkTimestamp)
 		proposerID   = blk.Proposer()
 	)
 
 	expectedProposerID, err := p.vm.Windower.ExpectedProposer(
 		ctx,
 		blkHeight,
 		parentPChainHeight,
-		proposer.TimeToSlot(parentTimestamp, blkTimestamp),
+		currentSlot,
 	)
 	switch {
 	case errors.Is(err, proposer.ErrAnyoneCanPropose):
@@ -386,7 +387,7 @@ func (p *postForkCommonComponents) verifyPostDurangoBlockDelay(
 	case expectedProposerID == proposerID:
 		return true, nil // block should be signed
 	default:
-		return false, errUnexpectedProposer
+		return false, fmt.Errorf("%w: slot %d expects %s", errUnexpectedProposer, currentSlot, expectedProposerID)
 	}
 }
 
@@ -454,7 +455,7 @@ func (p *postForkCommonComponents) shouldBuildSignedBlockPostDurango(
 	// In case the inner VM only issued one pendingTxs message, we should
 	// attempt to re-handle that once it is our turn to build the block.
 	p.vm.notifyInnerBlockReady()
-	return false, errProposerWindowNotStarted
+	return false, fmt.Errorf("%w: slot %d expects %s", errUnexpectedProposer, currentSlot, expectedProposerID)
 }
 
 func (p *postForkCommonComponents) shouldBuildSignedBlockPreDurango(
@@ -499,5 +500,5 @@ func (p *postForkCommonComponents) shouldBuildSignedBlockPreDurango(
 	// In case the inner VM only issued one pendingTxs message, we should
 	// attempt to re-handle that once it is our turn to build the block.
 	p.vm.notifyInnerBlockReady()
-	return false, errProposerWindowNotStarted
+	return false, fmt.Errorf("%w: delay %s < minDelay %s", errProposerWindowNotStarted, delay, minDelay)
 }

vms/proposervm/block_test.go

@@ -446,6 +446,6 @@ func TestPostDurangoBuildChildResetScheduler(t *testing.T) {
 			parentTimestamp,
 			pChainHeight-1,
 		)
-		require.ErrorIs(err, errProposerWindowNotStarted)
+		require.ErrorIs(err, errUnexpectedProposer)
 	}
 }