From 8c3faaa4c7a13c085637fbb7a4c62c87de86b83b Mon Sep 17 00:00:00 2001 From: Nishant Das Date: Tue, 24 Nov 2020 02:29:27 +0800 Subject: [PATCH] Add Back Error/Debug Logs (#7922) * add back logs * add back string * Reformat loggings Co-authored-by: Terence Tsao Co-authored-by: Preston Van Loon --- beacon-chain/sync/rate_limiter.go | 2 +- beacon-chain/sync/rpc.go | 2 +- beacon-chain/sync/service.go | 4 ++-- beacon-chain/sync/validate_beacon_blocks.go | 17 +++++++++++++++-- 4 files changed, 19 insertions(+), 6 deletions(-) diff --git a/beacon-chain/sync/rate_limiter.go b/beacon-chain/sync/rate_limiter.go index ecefa45c9..ad6cf4cc6 100644 --- a/beacon-chain/sync/rate_limiter.go +++ b/beacon-chain/sync/rate_limiter.go @@ -98,7 +98,7 @@ func (l *limiter) add(stream network.Stream, amt int64) { collector, err := l.retrieveCollector(topic) if err != nil { - log.Debugf("collector with topic '%s' does not exist", topic) + log.Errorf("collector with topic '%s' does not exist", topic) return } key := stream.Conn().RemotePeer().String() diff --git a/beacon-chain/sync/rpc.go b/beacon-chain/sync/rpc.go index a484fc054..8ea01e9a0 100644 --- a/beacon-chain/sync/rpc.go +++ b/beacon-chain/sync/rpc.go @@ -86,7 +86,7 @@ func (s *Service) registerRPC(baseTopic string, handle rpcHandler) { base, ok := p2p.RPCTopicMappings[baseTopic] if !ok { - log.Debugf("Could not retrieve base message for topic %s", baseTopic) + log.Errorf("Could not retrieve base message for topic %s", baseTopic) return } t := reflect.TypeOf(base) diff --git a/beacon-chain/sync/service.go b/beacon-chain/sync/service.go index 55673368a..5d1443852 100644 --- a/beacon-chain/sync/service.go +++ b/beacon-chain/sync/service.go @@ -254,7 +254,7 @@ func (s *Service) registerHandlers() { case statefeed.Initialized: data, ok := event.Data.(*statefeed.InitializedData) if !ok { - log.Debug("Event feed data is not type *statefeed.InitializedData") + log.Error("Event feed data is not type *statefeed.InitializedData") return } startTime := data.StartTime @@ -273,7 +273,7 @@ func (s *Service) registerHandlers() { case statefeed.Synced: _, ok := event.Data.(*statefeed.SyncedData) if !ok { - log.Debug("Event feed data is not type *statefeed.SyncedData") + log.Error("Event feed data is not type *statefeed.SyncedData") return } // Register respective pubsub handlers at state synced event. diff --git a/beacon-chain/sync/validate_beacon_blocks.go b/beacon-chain/sync/validate_beacon_blocks.go index b7a87a1f4..87e43964b 100644 --- a/beacon-chain/sync/validate_beacon_blocks.go +++ b/beacon-chain/sync/validate_beacon_blocks.go @@ -3,6 +3,7 @@ package sync import ( "context" "errors" + "fmt" "time" "github.com/libp2p/go-libp2p-core/peer" @@ -50,10 +51,12 @@ func (s *Service) validateBeaconBlockPubSub(ctx context.Context, pid peer.ID, ms blk, ok := m.(*ethpb.SignedBeaconBlock) if !ok { + log.WithError(errors.New("msg is not ethpb.SignedBeaconBlock")).Debug("Rejected block") return pubsub.ValidationReject } if blk.Block == nil { + log.WithError(errors.New("block.Block is nil")).Debug("Rejected block") return pubsub.ValidationReject } @@ -73,6 +76,7 @@ func (s *Service) validateBeaconBlockPubSub(ctx context.Context, pid peer.ID, ms blockRoot, err := blk.Block.HashTreeRoot() if err != nil { + log.WithError(err).WithField("blockSlot", blk.Block.Slot).Debug("Ignored block") return pubsub.ValidationIgnore } if s.db.HasBlock(ctx, blockRoot) { @@ -81,6 +85,8 @@ func (s *Service) validateBeaconBlockPubSub(ctx context.Context, pid peer.ID, ms // Check if parent is a bad block and then reject the block. if s.hasBadBlock(bytesutil.ToBytes32(blk.Block.ParentRoot)) { s.setBadBlock(ctx, blockRoot) + e := fmt.Errorf("received block with root %#x that has an invalid parent %#x", blockRoot, blk.Block.ParentRoot) + log.WithError(e).WithField("blockSlot", blk.Block.Slot).Debug("Rejected block") return pubsub.ValidationReject } @@ -92,19 +98,24 @@ func (s *Service) validateBeaconBlockPubSub(ctx context.Context, pid peer.ID, ms s.pendingQueueLock.RUnlock() if err := helpers.VerifySlotTime(uint64(s.chain.GenesisTime().Unix()), blk.Block.Slot, params.BeaconNetworkConfig().MaximumGossipClockDisparity); err != nil { + log.WithError(err).WithField("blockSlot", blk.Block.Slot).Debug("Ignored block") return pubsub.ValidationIgnore } // Add metrics for block arrival time subtracts slot start time. - if captureArrivalTimeMetric(uint64(s.chain.GenesisTime().Unix()), blk.Block.Slot) != nil { + if err := captureArrivalTimeMetric(uint64(s.chain.GenesisTime().Unix()), blk.Block.Slot); err != nil { + log.WithError(err).WithField("blockSlot", blk.Block.Slot).Debug("Ignored block") return pubsub.ValidationIgnore } startSlot, err := helpers.StartSlot(s.chain.FinalizedCheckpt().Epoch) if err != nil { + log.WithError(err).WithField("blockSlot", blk.Block.Slot).Debug("Ignored block") return pubsub.ValidationIgnore } if startSlot >= blk.Block.Slot { + e := fmt.Errorf("finalized slot %d greater or equal to block slot %d", startSlot, blk.Block.Slot) + log.WithError(e).WithField("blockSlot", blk.Block.Slot).Debug("Ignored block") return pubsub.ValidationIgnore } @@ -112,14 +123,16 @@ func (s *Service) validateBeaconBlockPubSub(ctx context.Context, pid peer.ID, ms if !s.db.HasBlock(ctx, bytesutil.ToBytes32(blk.Block.ParentRoot)) { s.pendingQueueLock.Lock() if err := s.insertBlockToPendingQueue(blk.Block.Slot, blk, blockRoot); err != nil { + log.WithError(err).WithField("blockSlot", blk.Block.Slot).Debug("Ignored block") return pubsub.ValidationIgnore } s.pendingQueueLock.Unlock() + log.WithError(errors.New("unknown parent")).WithField("blockSlot", blk.Block.Slot).Debug("Ignored block") return pubsub.ValidationIgnore } if err := s.validateBeaconBlock(ctx, blk, blockRoot); err != nil { - log.WithError(err).WithField("blockSlot", blk.Block.Slot).Warn("Could not validate beacon block") + log.WithError(err).WithField("blockSlot", blk.Block.Slot).Warn("Rejected block") return pubsub.ValidationReject }