beacon/log: augment logs with block roots (#5675)

* beacon/log: augment synced log with block root and finalized root
* beacon/log: augment initial sync log with block root
* beacon/sync: degrade pending block log to DEBUG level
* beacon/log: restore info level for state transition
* beacon/log: improve info logging
* Merge branch 'master' into q9-log-block
* Merge branch 'master' into q9-log-block

beacon-chain/blockchain/log.go

@@ -1,6 +1,7 @@
 package blockchain
 
 import (
+	"encoding/hex"
 	"fmt"
 
 	ethpb "github.com/prysmaticlabs/ethereumapis/eth/v1alpha1"
@@ -15,7 +16,6 @@ var log = logrus.WithField("prefix", "blockchain")
 // logs state transition related data every slot.
 func logStateTransitionData(b *ethpb.BeaconBlock) {
 	log.WithFields(logrus.Fields{
-		"slot":              b.Slot,
 		"attestations":      len(b.Body.Attestations),
 		"deposits":          len(b.Body.Deposits),
 		"attesterSlashings": len(b.Body.AttesterSlashings),
@@ -24,6 +24,16 @@ func logStateTransitionData(b *ethpb.BeaconBlock) {
 	}).Info("Finished applying state transition")
 }
 
+func logBlockSyncStatus(block *ethpb.BeaconBlock, blockRoot [32]byte, finalized *ethpb.Checkpoint) {
+	log.WithFields(logrus.Fields{
+		"slot":           block.Slot,
+		"block":          fmt.Sprintf("0x%s...", hex.EncodeToString(blockRoot[:])[:8]),
+		"epoch":          helpers.SlotToEpoch(block.Slot),
+		"finalizedEpoch": finalized.Epoch,
+		"finalizedRoot":  fmt.Sprintf("0x%s...", hex.EncodeToString(finalized.Root[:])[:8]),
+	}).Info("Synced new block")
+}
+
 func logEpochData(beaconState *stateTrie.BeaconState) {
 	log.WithFields(logrus.Fields{
 		"epoch":                  helpers.CurrentEpoch(beaconState),

beacon-chain/blockchain/process_block.go

@@ -77,7 +77,7 @@ func (s *Service) onBlock(ctx context.Context, signed *ethpb.SignedBeaconBlock)
 	log.WithFields(logrus.Fields{
 		"slot": b.Slot,
 		"root": fmt.Sprintf("0x%s...", hex.EncodeToString(root[:])[:8]),
-	}).Info("Executing state transition on block")
+	}).Debug("Executing state transition on block")
 
 	postState, err := state.ExecuteStateTransition(ctx, preState, signed)
 	if err != nil {

beacon-chain/blockchain/receive_block.go

@@ -118,6 +118,9 @@ func (s *Service) ReceiveBlockNoPubsub(ctx context.Context, block *ethpb.SignedB
 	// Reports on block and fork choice metrics.
 	reportSlotMetrics(blockCopy.Block.Slot, s.headSlot(), s.CurrentSlot(), s.finalizedCheckpt)
 
+	// Log block sync status.
+	logBlockSyncStatus(blockCopy.Block, root, s.finalizedCheckpt)
+
 	// Log state transition data.
 	logStateTransitionData(blockCopy.Block)
 
@@ -168,6 +171,9 @@ func (s *Service) ReceiveBlockNoPubsubForkchoice(ctx context.Context, block *eth
 	// Reports on block and fork choice metrics.
 	reportSlotMetrics(blockCopy.Block.Slot, s.headSlot(), s.CurrentSlot(), s.finalizedCheckpt)
 
+	// Log block sync status.
+	logBlockSyncStatus(blockCopy.Block, root, s.finalizedCheckpt)
+
 	// Log state transition data.
 	logStateTransitionData(blockCopy.Block)
 

beacon-chain/sync/initial-sync/BUILD.bazel

@@ -22,6 +22,7 @@ go_library(
         "//beacon-chain/db:go_default_library",
         "//beacon-chain/flags:go_default_library",
         "//beacon-chain/p2p:go_default_library",
+        "//beacon-chain/state/stateutil:go_default_library",
         "//beacon-chain/sync:go_default_library",
         "//proto/beacon/p2p/v1:go_default_library",
         "//shared:go_default_library",

beacon-chain/sync/initial-sync/round_robin.go

@@ -2,6 +2,7 @@ package initialsync
 
 import (
 	"context"
+	"encoding/hex"
 	"fmt"
 	"io"
 	"time"
@@ -15,6 +16,7 @@ import (
 	"github.com/prysmaticlabs/prysm/beacon-chain/core/helpers"
 	"github.com/prysmaticlabs/prysm/beacon-chain/core/state"
 	"github.com/prysmaticlabs/prysm/beacon-chain/p2p"
+	"github.com/prysmaticlabs/prysm/beacon-chain/state/stateutil"
 	prysmsync "github.com/prysmaticlabs/prysm/beacon-chain/sync"
 	p2ppb "github.com/prysmaticlabs/prysm/proto/beacon/p2p/v1"
 	"github.com/prysmaticlabs/prysm/shared/bytesutil"
@@ -179,6 +181,11 @@ func (s *Service) logSyncStatus(genesis time.Time, blk *eth.BeaconBlock, counter
 		rate = 1
 	}
 	timeRemaining := time.Duration(float64(helpers.SlotsSince(genesis)-blk.Slot)/rate) * time.Second
+	blockRoot := "unknown"
+	root, err := stateutil.BlockRoot(blk)
+	if err == nil {
+		blockRoot = fmt.Sprintf("0x%s...", hex.EncodeToString(root[:])[:8])
+	}
 	log.WithField(
 		"peers",
 		len(s.p2p.Peers().Connected()),
@@ -186,7 +193,8 @@ func (s *Service) logSyncStatus(genesis time.Time, blk *eth.BeaconBlock, counter
 		"blocksPerSecond",
 		fmt.Sprintf("%.1f", rate),
 	).Infof(
-		"Processing block %d/%d - estimated time remaining %s",
+		"Processing block %s %d/%d - estimated time remaining %s",
+		blockRoot,
 		blk.Slot,
 		helpers.SlotsSince(genesis),
 		timeRemaining,

beacon-chain/sync/pending_blocks_queue.go

@@ -130,7 +130,7 @@ func (r *Service) processPendingBlocks(ctx context.Context) error {
 		log.WithFields(logrus.Fields{
 			"slot":      s,
 			"blockRoot": hex.EncodeToString(bytesutil.Trunc(blkRoot[:])),
-		}).Info("Processed pending block and cleared it in cache")
+		}).Debug("Processed pending block and cleared it in cache")
 
 		span.End()
 	}