diff --git a/beacon-chain/blockchain/log.go b/beacon-chain/blockchain/log.go index ce4037442b9d..8bf57bcab731 100644 --- a/beacon-chain/blockchain/log.go +++ b/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), diff --git a/beacon-chain/blockchain/process_block.go b/beacon-chain/blockchain/process_block.go index 8f84abaaedf1..e55cffe1ef89 100644 --- a/beacon-chain/blockchain/process_block.go +++ b/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 { diff --git a/beacon-chain/blockchain/receive_block.go b/beacon-chain/blockchain/receive_block.go index 892781b52426..6db67b29d442 100644 --- a/beacon-chain/blockchain/receive_block.go +++ b/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) diff --git a/beacon-chain/sync/initial-sync/BUILD.bazel b/beacon-chain/sync/initial-sync/BUILD.bazel index 991796a6dc2e..dd5cb236a7ce 100644 --- a/beacon-chain/sync/initial-sync/BUILD.bazel +++ b/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", diff --git a/beacon-chain/sync/initial-sync/round_robin.go b/beacon-chain/sync/initial-sync/round_robin.go index 89e12375da22..7f28558c3e78 100644 --- a/beacon-chain/sync/initial-sync/round_robin.go +++ b/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, diff --git a/beacon-chain/sync/pending_blocks_queue.go b/beacon-chain/sync/pending_blocks_queue.go index 27bb20b0ca68..b10e79e7a59b 100644 --- a/beacon-chain/sync/pending_blocks_queue.go +++ b/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() }