Sampling: Improve logging.

beacon-chain/sync/data_columns_sampling.go

@@ -247,27 +247,12 @@ func (d *dataColumnSampler1D) handleStateNotification(ctx context.Context, event
 	// Randomize columns for sample selection.
 	randomizedColumns := randomizeColumns(d.nonCustodyColumns)
 	samplesCount := min(params.BeaconConfig().SamplesPerSlot, uint64(len(d.nonCustodyColumns))-params.BeaconConfig().NumberOfColumns/2)
-	ok, summaries, err := d.incrementalDAS(ctx, data.BlockRoot, randomizedColumns, samplesCount)
+
+	// TODO: Use the first output of `incrementalDAS` as input of the fork choice rule.
+	_, _, err = d.incrementalDAS(ctx, data.BlockRoot, randomizedColumns, samplesCount)
 	if err != nil {
 		log.WithError(err).Error("Failed to run incremental DAS")
 	}
-
-	if ok {
-		requestedColumns := summaries[0].RequestedColumns
-		for _, summary := range summaries[1:] {
-			requestedColumns = append(requestedColumns, summary.RequestedColumns...)
-		}
-
-		log.WithFields(logrus.Fields{
-			"root":    fmt.Sprintf("%#x", data.BlockRoot),
-			"columns": requestedColumns,
-		}).Debug("Data column sampling successful")
-	} else {
-		log.WithFields(logrus.Fields{
-			"root":    fmt.Sprintf("%#x", data.BlockRoot),
-			"columns": randomizedColumns,
-		}).Warning("Data column sampling failed")
-	}
 }
 
 // incrementalDAS samples data columns from active peers using incremental DAS.
@@ -283,17 +268,28 @@ func (d *dataColumnSampler1D) incrementalDAS(
 	firstColumnToSample, extendedSampleCount := uint64(0), peerdas.ExtendedSampleCount(sampleCount, allowedFailures)
 	roundSummaries := make([]roundSummary, 0, 1) // We optimistically allocate only one round summary.
 
+	start := time.Now()
+
 	for round := 1; ; /*No exit condition */ round++ {
 		if extendedSampleCount > uint64(len(columns)) {
 			// We already tried to sample all possible columns, this is the unhappy path.
-			log.WithField("root", fmt.Sprintf("%#x", root)).Warning("Some columns are still missing after sampling all possible columns")
+			log.WithFields(logrus.Fields{
+				"root":  fmt.Sprintf("%#x", root),
+				"round": round - 1,
+			}).Warning("Some columns are still missing after trying to sample all possible columns")
 			return false, roundSummaries, nil
 		}
 
 		// Get the columns to sample for this round.
 		columnsToSample := columns[firstColumnToSample:extendedSampleCount]
 		columnsToSampleCount := extendedSampleCount - firstColumnToSample
 
+		log.WithFields(logrus.Fields{
+			"root":    fmt.Sprintf("%#x", root),
+			"columns": columnsToSample,
+			"round":   round,
+		}).Debug("Start data columns sampling")
+
 		// Sample data columns from peers in parallel.
 		retrievedSamples := d.sampleDataColumns(ctx, root, columnsToSample)
 
@@ -314,7 +310,8 @@ func (d *dataColumnSampler1D) incrementalDAS(
 			// All columns were correctly sampled, this is the happy path.
 			log.WithFields(logrus.Fields{
 				"root":         fmt.Sprintf("%#x", root),
-				"roundsNeeded": round,
+				"neededRounds": round,
+				"duration":     time.Since(start),
 			}).Debug("All columns were successfully sampled")
 			return true, roundSummaries, nil
 		}
@@ -432,14 +429,14 @@ func (d *dataColumnSampler1D) sampleDataColumnsFromPeer(
 			"peerID":           pid,
 			"root":             fmt.Sprintf("%#x", root),
 			"requestedColumns": sortedSliceFromMap(requestedColumns),
-		}).Debug("All requested columns were successfully sampled from peer")
+		}).Debug("Sampled columns from peer successfully")
 	} else {
 		log.WithFields(logrus.Fields{
 			"peerID":           pid,
 			"root":             fmt.Sprintf("%#x", root),
 			"requestedColumns": sortedSliceFromMap(requestedColumns),
 			"retrievedColumns": sortedSliceFromMap(retrievedColumns),
-		}).Debug("Some requested columns were not sampled from peer")
+		}).Debug("Sampled columns from peer with some errors")
 	}
 
 	return retrievedColumns

beacon-chain/sync/rpc_data_column_sidecars_by_root.go

@@ -94,7 +94,7 @@ func (s *Service) dataColumnSidecarByRootRPCHandler(ctx context.Context, msg int
 		"requested":      requestedColumnsList,
 		"custodiedCount": len(custodiedColumnsList),
 		"requestedCount": len(requestedColumnsList),
-	}).Debug("Received data column sidecar by root request")
+	}).Debug("Data column sidecar by root request received")
 
 	// Subscribe to the data column feed.
 	rootIndexChan := make(chan filesystem.RootIndexPair)

beacon-chain/sync/rpc_send_request.go

@@ -232,7 +232,6 @@ func SendDataColumnSidecarByRoot(
 	}
 
 	// Send the request to the peer.
-	log.WithField("topic", topic).Debug("Sending data column sidecar request")
 	stream, err := p2pApi.Send(ctx, req, topic, pid)
 	if err != nil {
 		return nil, errors.Wrap(err, "send")