From b45e87abd65ca418f0babb6bc2ee5baf562f6a1c Mon Sep 17 00:00:00 2001 From: Manu NALEPA Date: Tue, 7 Oct 2025 20:44:55 +0200 Subject: [PATCH] Move some logs to trace (#15816) * Prettify logs for byRange/byRoot data column sidecar requests. * Moving byRoot/byRange data column sidecars requests from peers to TRACE level. * Move "Peer requested blob sidecar by root not found in db" in TRACE. * Add changelog. * Fix Kasey's comment. * Apply Kasey's suggestion. --- .../sync/rpc_blob_sidecars_by_root.go | 18 ++++++----- .../sync/rpc_data_column_sidecars_by_range.go | 31 +++++++++---------- .../sync/rpc_data_column_sidecars_by_root.go | 30 +++++++++--------- changelog/manu-logs-to-trace.md | 4 +++ 4 files changed, 43 insertions(+), 40 deletions(-) create mode 100644 changelog/manu-logs-to-trace.md diff --git a/beacon-chain/sync/rpc_blob_sidecars_by_root.go b/beacon-chain/sync/rpc_blob_sidecars_by_root.go index a6e66aaec4..b1d226216d 100644 --- a/beacon-chain/sync/rpc_blob_sidecars_by_root.go +++ b/beacon-chain/sync/rpc_blob_sidecars_by_root.go @@ -72,17 +72,21 @@ func (s *Service) blobSidecarByRootRPCHandler(ctx context.Context, msg interface root, idx := bytesutil.ToBytes32(blobIdents[i].BlockRoot), blobIdents[i].Index sc, err := s.cfg.blobStorage.Get(root, idx) if err != nil { + log := log.WithFields(logrus.Fields{ + "root": fmt.Sprintf("%#x", root), + "index": idx, + "peer": remotePeer.String(), + }) + if db.IsNotFound(err) { - log.WithError(err).WithFields(logrus.Fields{ - "root": fmt.Sprintf("%#x", root), - "index": idx, - "peer": remotePeer.String(), - }).Debugf("Peer requested blob sidecar by root not found in db") + log.Trace("Peer requested blob sidecar by root not found in db") continue } - log.WithError(err).Errorf("unexpected db error retrieving BlobSidecar, root=%x, index=%d", root, idx) + + log.Error("Unexpected DB error retrieving blob sidecar from storage") s.writeErrorResponseToStream(responseCodeServerError, types.ErrGeneric.Error(), stream) - return err + + return errors.Wrap(err, "get blob sidecar by root") } // If any root in the request content references a block earlier than minimum_request_epoch, diff --git a/beacon-chain/sync/rpc_data_column_sidecars_by_range.go b/beacon-chain/sync/rpc_data_column_sidecars_by_range.go index 056a182439..e64ef8ef64 100644 --- a/beacon-chain/sync/rpc_data_column_sidecars_by_range.go +++ b/beacon-chain/sync/rpc_data_column_sidecars_by_range.go @@ -5,6 +5,7 @@ import ( "slices" "time" + "github.com/OffchainLabs/prysm/v6/beacon-chain/core/helpers" p2ptypes "github.com/OffchainLabs/prysm/v6/beacon-chain/p2p/types" "github.com/OffchainLabs/prysm/v6/config/params" "github.com/OffchainLabs/prysm/v6/consensus-types/primitives" @@ -41,21 +42,17 @@ func (s *Service) dataColumnSidecarsByRangeRPCHandler(ctx context.Context, msg i maxRequestDataColumnSidecars := beaconConfig.MaxRequestDataColumnSidecars remotePeer := stream.Conn().RemotePeer() - requestedColumns := request.Columns - - // Format log fields. - var requestedColumnsLog interface{} = "all" - if uint64(len(requestedColumns)) != beaconConfig.NumberOfColumns { - requestedColumnsLog = requestedColumns - } - log := log.WithFields(logrus.Fields{ - "remotePeer": remotePeer, - "requestedColumns": requestedColumnsLog, - "startSlot": request.StartSlot, - "count": request.Count, + "remotePeer": remotePeer, + "startSlot": request.StartSlot, + "count": request.Count, }) + if log.Logger.Level >= logrus.DebugLevel { + slices.Sort(request.Columns) + log = log.WithField("requestedColumns", helpers.PrettySlice(request.Columns)) + } + // Validate the request regarding rate limiting. if err := s.rateLimiter.validateRequest(stream, rateLimitingAmount); err != nil { return errors.Wrap(err, "rate limiter validate request") @@ -69,13 +66,13 @@ func (s *Service) dataColumnSidecarsByRangeRPCHandler(ctx context.Context, msg i tracing.AnnotateError(span, err) return errors.Wrap(err, "validate data columns by range") } + + log.Trace("Serving data column sidecars by range") + if rangeParameters == nil { - log.Debug("No data columns by range to serve") return nil } - log.Debug("Serving data columns by range request") - // Ticker to stagger out large requests. ticker := time.NewTicker(time.Second) @@ -104,13 +101,13 @@ func (s *Service) dataColumnSidecarsByRangeRPCHandler(ctx context.Context, msg i // Once the quota is reached, we're done serving the request. if maxRequestDataColumnSidecars == 0 { - log.WithField("initialQuota", beaconConfig.MaxRequestDataColumnSidecars).Debug("Reached quota for data column sidecars by range request") + log.WithField("initialQuota", beaconConfig.MaxRequestDataColumnSidecars).Trace("Reached quota for data column sidecars by range request") break } } if err := batch.error(); err != nil { - log.WithError(err).Debug("Error in DataColumnSidecarsByRange batch") + log.WithError(err).Error("Cannot get next batch of blocks") // If we hit a rate limit, the error response has already been written, and the stream is already closed. if !errors.Is(err, p2ptypes.ErrRateLimited) { diff --git a/beacon-chain/sync/rpc_data_column_sidecars_by_root.go b/beacon-chain/sync/rpc_data_column_sidecars_by_root.go index ec040b27c8..1de8a21bfb 100644 --- a/beacon-chain/sync/rpc_data_column_sidecars_by_root.go +++ b/beacon-chain/sync/rpc_data_column_sidecars_by_root.go @@ -7,6 +7,7 @@ import ( "slices" "time" + "github.com/OffchainLabs/prysm/v6/beacon-chain/core/helpers" "github.com/OffchainLabs/prysm/v6/beacon-chain/p2p/types" "github.com/OffchainLabs/prysm/v6/cmd/beacon-chain/flags" fieldparams "github.com/OffchainLabs/prysm/v6/config/fieldparams" @@ -33,7 +34,6 @@ func (s *Service) dataColumnSidecarByRootRPCHandler(ctx context.Context, msg int defer span.End() batchSize := flags.Get().DataColumnBatchLimit - numberOfColumns := params.BeaconConfig().NumberOfColumns // Check if the message type is the one expected. ref, ok := msg.(types.DataColumnsByRootIdentifiers) @@ -68,26 +68,13 @@ func (s *Service) dataColumnSidecarByRootRPCHandler(ctx context.Context, msg int slices.Sort(columns) } - // Format nice logs. - requestedColumnsByRootLog := make(map[string]interface{}) - for root, columns := range requestedColumnsByRoot { - rootStr := fmt.Sprintf("%#x", root) - requestedColumnsByRootLog[rootStr] = "all" - if uint64(len(columns)) != numberOfColumns { - requestedColumnsByRootLog[rootStr] = columns - } - } - // Compute the oldest slot we'll allow a peer to request, based on the current slot. minReqSlot, err := dataColumnsRPCMinValidSlot(s.cfg.clock.CurrentSlot()) if err != nil { return errors.Wrapf(err, "data columns RPC min valid slot") } - log := log.WithFields(logrus.Fields{ - "peer": remotePeer, - "columns": requestedColumnsByRootLog, - }) + log := log.WithField("peer", remotePeer) defer closeStream(stream, log) @@ -96,7 +83,18 @@ func (s *Service) dataColumnSidecarByRootRPCHandler(ctx context.Context, msg int ticker = time.NewTicker(tickerDelay) } - log.Debug("Serving data column sidecar by root request") + if log.Logger.Level >= logrus.TraceLevel { + // We optimistially assume the peer requests the same set of columns for all roots, + // pre-sizing the map accordingly. + requestedRootsByColumnSet := make(map[string][]string, 1) + for root, columns := range requestedColumnsByRoot { + slices.Sort(columns) + prettyColumns := helpers.PrettySlice(columns) + requestedRootsByColumnSet[prettyColumns] = append(requestedRootsByColumnSet[prettyColumns], fmt.Sprintf("%#x", root)) + } + + log.WithField("requested", requestedRootsByColumnSet).Trace("Serving data column sidecars by root") + } count := 0 for _, ident := range requestedColumnIdents { diff --git a/changelog/manu-logs-to-trace.md b/changelog/manu-logs-to-trace.md new file mode 100644 index 0000000000..53afd4a44c --- /dev/null +++ b/changelog/manu-logs-to-trace.md @@ -0,0 +1,4 @@ +### Ignored +- Prettify logs for byRange/byRoot data column sidecar requests. +- Moving byRoot/byRange data column sidecars requests from peers to TRACE level. +- Move "Peer requested blob sidecar by root not found in db" in TRACE. \ No newline at end of file