From 35fc1c976f2868c42de17f3b8967a2019067fae6 Mon Sep 17 00:00:00 2001 From: terencechain Date: Mon, 11 Sep 2023 13:46:06 -0700 Subject: [PATCH] Improved Logging for Blob Sidecar (#12883) * feat: improve blob sidecar logs * Kasey's feedback --- beacon-chain/blockchain/log.go | 14 +++++++++++++- beacon-chain/blockchain/process_block.go | 14 ++++++++++++-- .../rpc/prysm/v1alpha1/validator/proposer.go | 4 ++++ beacon-chain/sync/initial-sync/round_robin.go | 13 +++++++++++++ beacon-chain/sync/rpc_beacon_blocks_by_root.go | 5 +++++ beacon-chain/sync/subscriber_blob_sidecar.go | 2 -- beacon-chain/sync/validate_blob.go | 11 +++++++++++ cmd/prysmctl/p2p/request_blobs.go | 4 ++-- validator/client/propose.go | 2 +- 9 files changed, 61 insertions(+), 8 deletions(-) diff --git a/beacon-chain/blockchain/log.go b/beacon-chain/blockchain/log.go index 3d0c469cf0..4cc692bc50 100644 --- a/beacon-chain/blockchain/log.go +++ b/beacon-chain/blockchain/log.go @@ -66,7 +66,7 @@ func logStateTransitionData(b interfaces.ReadOnlyBeaconBlock) error { if err != nil { log.WithError(err).Error("Failed to get blob KZG commitments") } else if len(kzgs) > 0 { - log = log.WithField("blobCommitmentCount", len(kzgs)) + log = log.WithField("kzgCommitmentCount", len(kzgs)) } } log.Info("Finished applying state transition") @@ -147,3 +147,15 @@ func logPayload(block interfaces.ReadOnlyBeaconBlock) error { log.WithFields(fields).Debug("Synced new payload") return nil } + +func logBlobSidecar(scs []*ethpb.BlobSidecar, startTime time.Time) { + if len(scs) == 0 { + return + } + log.WithFields(logrus.Fields{ + "count": len(scs), + "slot": scs[0].Slot, + "block": hex.EncodeToString(scs[0].BlockRoot), + "validationTime": time.Since(startTime), + }).Debug("Synced new blob sidecars") +} diff --git a/beacon-chain/blockchain/process_block.go b/beacon-chain/blockchain/process_block.go index 2b603c6e00..2cfb1f08a5 100644 --- a/beacon-chain/blockchain/process_block.go +++ b/beacon-chain/blockchain/process_block.go @@ -533,6 +533,8 @@ func (s *Service) isDataAvailable(ctx context.Context, root [32]byte, signed int if signed.Version() < version.Deneb { return nil } + t := time.Now() + block := signed.Block() if block == nil { return errors.New("invalid nil beacon block") @@ -565,7 +567,11 @@ func (s *Service) isDataAvailable(ctx context.Context, root [32]byte, signed int if len(sidecars) >= existingBlobs { delete(s.blobNotifier.chanForRoot, root) s.blobNotifier.Unlock() - return kzg.IsDataAvailable(kzgCommitments, sidecars) + if err := kzg.IsDataAvailable(kzgCommitments, sidecars); err != nil { + return err + } + logBlobSidecar(sidecars, t) + return nil } } // Create the channel if it didn't exist already the index map will be @@ -594,7 +600,11 @@ func (s *Service) isDataAvailable(ctx context.Context, root [32]byte, signed int if err != nil { return errors.Wrap(err, "could not get blob sidecars") } - return kzg.IsDataAvailable(kzgCommitments, sidecars) + if err := kzg.IsDataAvailable(kzgCommitments, sidecars); err != nil { + return err + } + logBlobSidecar(sidecars, t) + return nil } case <-ctx.Done(): return errors.Wrap(ctx.Err(), "context deadline waiting for blob sidecars") diff --git a/beacon-chain/rpc/prysm/v1alpha1/validator/proposer.go b/beacon-chain/rpc/prysm/v1alpha1/validator/proposer.go index 9471967cfe..b22e8ff6e9 100644 --- a/beacon-chain/rpc/prysm/v1alpha1/validator/proposer.go +++ b/beacon-chain/rpc/prysm/v1alpha1/validator/proposer.go @@ -350,6 +350,10 @@ func (vs *Server) ProposeBeaconBlock(ctx context.Context, req *ethpb.GenericSign } sidecars := make([]*ethpb.BlobSidecar, len(scs)) for i, sc := range scs { + log.WithFields(logrus.Fields{ + "blockRoot": hex.EncodeToString(sc.Message.BlockRoot), + "index": sc.Message.Index, + }).Debug("Broadcasting blob sidecar") if err := vs.P2P.BroadcastBlob(ctx, sc.Message.Index, sc); err != nil { log.WithError(err).Errorf("Could not broadcast blob sidecar index %d / %d", i, len(scs)) } diff --git a/beacon-chain/sync/initial-sync/round_robin.go b/beacon-chain/sync/initial-sync/round_robin.go index 89df36b2e9..f7dad22c54 100644 --- a/beacon-chain/sync/initial-sync/round_robin.go +++ b/beacon-chain/sync/initial-sync/round_robin.go @@ -307,6 +307,9 @@ func (s *Service) processBatchedBlocks(ctx context.Context, genesis time.Time, if err != nil { return err } + if len(bwb) == 0 { + return nil + } first := bwb[0].Block if !s.cfg.Chain.HasBlock(ctx, first.Block().ParentRoot()) { @@ -314,6 +317,7 @@ func (s *Service) processBatchedBlocks(ctx context.Context, genesis time.Time, errParentDoesNotExist, first.Block().ParentRoot(), first.Block().Slot()) } s.logBatchSyncStatus(genesis, first, len(bwb)) + blobCount := 0 for _, bb := range bwb { if len(bb.Blobs) == 0 { continue @@ -321,7 +325,16 @@ func (s *Service) processBatchedBlocks(ctx context.Context, genesis time.Time, if err := s.cfg.DB.SaveBlobSidecar(ctx, bb.Blobs); err != nil { return errors.Wrapf(err, "failed to save blobs for block %#x", bb.Block.Root()) } + blobCount += len(bb.Blobs) } + if blobCount > 0 { + log.WithFields(logrus.Fields{ + "startSlot": bwb[0].Block.Block().Slot(), + "endSlot": bwb[len(bwb)-1].Block.Block().Slot(), + "count": blobCount, + }).Info("Processed blob sidecars") + } + return bFunc(ctx, blocks.BlockWithVerifiedBlobsSlice(bwb).ROBlocks()) } diff --git a/beacon-chain/sync/rpc_beacon_blocks_by_root.go b/beacon-chain/sync/rpc_beacon_blocks_by_root.go index c684942f35..88c80c3ceb 100644 --- a/beacon-chain/sync/rpc_beacon_blocks_by_root.go +++ b/beacon-chain/sync/rpc_beacon_blocks_by_root.go @@ -145,5 +145,10 @@ func (s *Service) requestPendingBlobs(ctx context.Context, b interfaces.ReadOnly if err != nil { return err } + + for _, sidecar := range blobSidecars { + log.WithFields(blobFields(sidecar)).Debug("Received blob sidecar gossip RPC") + } + return s.cfg.beaconDB.SaveBlobSidecar(ctx, blobSidecars) } diff --git a/beacon-chain/sync/subscriber_blob_sidecar.go b/beacon-chain/sync/subscriber_blob_sidecar.go index c319d42f40..9ec14ca322 100644 --- a/beacon-chain/sync/subscriber_blob_sidecar.go +++ b/beacon-chain/sync/subscriber_blob_sidecar.go @@ -14,8 +14,6 @@ func (s *Service) blobSubscriber(ctx context.Context, msg proto.Message) error { return fmt.Errorf("message was not type *eth.SignedBlobSidecar, type=%T", msg) } - log.WithFields(blobFields(b.Message)).Debug("Received blob sidecar") - s.setSeenBlobIndex(b.Message.Blob, b.Message.Index) if err := s.cfg.beaconDB.SaveBlobSidecar(ctx, []*eth.BlobSidecar{b.Message}); err != nil { diff --git a/beacon-chain/sync/validate_blob.go b/beacon-chain/sync/validate_blob.go index 5847860fa2..1afc285410 100644 --- a/beacon-chain/sync/validate_blob.go +++ b/beacon-chain/sync/validate_blob.go @@ -17,11 +17,14 @@ import ( "github.com/prysmaticlabs/prysm/v4/encoding/bytesutil" "github.com/prysmaticlabs/prysm/v4/network/forks" eth "github.com/prysmaticlabs/prysm/v4/proto/prysm/v1alpha1" + prysmTime "github.com/prysmaticlabs/prysm/v4/time" "github.com/prysmaticlabs/prysm/v4/time/slots" "github.com/sirupsen/logrus" ) func (s *Service) validateBlob(ctx context.Context, pid peer.ID, msg *pubsub.Message) (pubsub.ValidationResult, error) { + receivedTime := prysmTime.Now() + if pid == s.cfg.p2p.PeerID() { return pubsub.ValidationAccept, nil } @@ -125,6 +128,14 @@ func (s *Service) validateBlob(ctx context.Context, pid peer.ID, msg *pubsub.Mes return pubsub.ValidationReject, err } + startTime, err := slots.ToTime(genesisTime, blob.Slot) + if err != nil { + return pubsub.ValidationIgnore, err + } + fields := blobFields(blob) + fields["sinceSlotStartTime"] = receivedTime.Sub(startTime) + fields["validationTime"] = prysmTime.Now().Sub(receivedTime) + log.WithFields(fields).Debug("Received blob sidecar gossip") msg.ValidatorData = sBlob return pubsub.ValidationAccept, nil diff --git a/cmd/prysmctl/p2p/request_blobs.go b/cmd/prysmctl/p2p/request_blobs.go index d55510d6b3..7f57dc0f48 100644 --- a/cmd/prysmctl/p2p/request_blobs.go +++ b/cmd/prysmctl/p2p/request_blobs.go @@ -181,12 +181,12 @@ func cliActionRequestBlobs(cliCtx *cli.Context) error { "index": b.Index, "commitment": fmt.Sprintf("%#x", b.KzgCommitment), "kzgProof": fmt.Sprintf("%#x", b.KzgProof), - }).Info("Received blob") + }).Info("Received blob sidecar") } log.WithFields(logrus.Fields{ "numBlobs": len(blobs), "peer": pr.String(), - }).Info("Received blobs from peer") + }).Info("Received blob sidecars from peer") } return nil } diff --git a/validator/client/propose.go b/validator/client/propose.go index 90f375a300..6c63d69410 100644 --- a/validator/client/propose.go +++ b/validator/client/propose.go @@ -211,7 +211,7 @@ func (v *validator) ProposeBlock(ctx context.Context, slot primitives.Slot, pubK log.WithError(err).Error("Failed to get blob KZG commitments") return } else if len(kzgs) != 0 { - log = log.WithField("blobCommitmentCount", len(kzgs)) + log = log.WithField("kzgCommitmentCount", len(kzgs)) } } }