Add More Visibility Into Sync Committee Message Participation (#10943)

* build

* granular time message

* timing

* log

Co-authored-by: prylabs-bulldozer[bot] <58059840+prylabs-bulldozer[bot]@users.noreply.github.com>

beacon-chain/core/altair/sync_committee.go

@@ -214,9 +214,12 @@ func ValidateSyncMessageTime(slot types.Slot, genesisTime time.Time, clockDispar
 	// Verify sync message slot is within the time range.
 	if messageTime.Before(lowerBound) || messageTime.After(upperBound) {
 		return fmt.Errorf(
-			"sync message slot %d not within allowable range of %d to %d (current slot)",
+			"sync message time %v (slot %d) not within allowable range of %v (slot %d) to %v (slot %d)",
+			messageTime,
 			slot,
+			lowerBound,
 			uint64(lowerBound.Unix()-genesisTime.Unix())/params.BeaconConfig().SecondsPerSlot,
+			upperBound,
 			uint64(upperBound.Unix()-genesisTime.Unix())/params.BeaconConfig().SecondsPerSlot,
 		)
 	}

beacon-chain/core/altair/sync_committee_test.go

@@ -328,7 +328,7 @@ func Test_ValidateSyncMessageTime(t *testing.T) {
 				syncMessageSlot: 16,
 				genesisTime:     prysmTime.Now().Add(-(15 * time.Duration(params.BeaconConfig().SecondsPerSlot) * time.Second)),
 			},
-			wantedErr: "sync message slot 16 not within allowable range of",
+			wantedErr: "(slot 16) not within allowable range of",
 		},
 		{
 			name: "sync_message.slot == current_slot+CLOCK_DISPARITY",
@@ -344,7 +344,7 @@ func Test_ValidateSyncMessageTime(t *testing.T) {
 				syncMessageSlot: 100,
 				genesisTime:     prysmTime.Now().Add(-(100 * time.Duration(params.BeaconConfig().SecondsPerSlot) * time.Second) + params.BeaconNetworkConfig().MaximumGossipClockDisparity + 1000*time.Millisecond),
 			},
-			wantedErr: "sync message slot 100 not within allowable range of",
+			wantedErr: "(slot 100) not within allowable range of",
 		},
 		{
 			name: "sync_message.slot == current_slot-CLOCK_DISPARITY",
@@ -360,7 +360,7 @@ func Test_ValidateSyncMessageTime(t *testing.T) {
 				syncMessageSlot: 101,
 				genesisTime:     prysmTime.Now().Add(-(100*time.Duration(params.BeaconConfig().SecondsPerSlot)*time.Second + params.BeaconNetworkConfig().MaximumGossipClockDisparity)),
 			},
-			wantedErr: "sync message slot 101 not within allowable range of",
+			wantedErr: "(slot 101) not within allowable range of",
 		},
 		{
 			name: "sync_message.slot is well beyond current slot",

validator/accounts/testing/mock.go

@@ -83,6 +83,8 @@ type MockValidator struct {
 	Km keymanager.IKeymanager
 }
 
+func (_ MockValidator) LogSyncCommitteeMessagesSubmitted() {}
+
 func (_ MockValidator) Done() {
 	panic("implement me")
 }

validator/client/iface/validator.go

@@ -49,6 +49,7 @@ type Validator interface {
 	SubmitSyncCommitteeMessage(ctx context.Context, slot types.Slot, pubKey [fieldparams.BLSPubkeyLength]byte)
 	SubmitSignedContributionAndProof(ctx context.Context, slot types.Slot, pubKey [fieldparams.BLSPubkeyLength]byte)
 	LogAttestationsSubmitted()
+	LogSyncCommitteeMessagesSubmitted()
 	LogNextDutyTimeLeft(slot types.Slot) error
 	UpdateDomainDataCaches(ctx context.Context, slot types.Slot)
 	WaitForKeymanagerInitialization(ctx context.Context) error

validator/client/log.go

@@ -2,6 +2,7 @@ package client
 
 import (
 	"fmt"
+	"sync/atomic"
 	"time"
 
 	"github.com/prysmaticlabs/prysm/config/params"
@@ -43,6 +44,13 @@ func (v *validator) LogAttestationsSubmitted() {
 	v.attLogs = make(map[[32]byte]*attSubmitted)
 }
 
+// LogSyncCommitteeMessagesSubmitted logs info about submitted sync committee messages.
+func (v *validator) LogSyncCommitteeMessagesSubmitted() {
+	log.WithField("messages", v.syncCommitteeStats.totalMessagesSubmitted).Debug("Submitted sync committee messages successfully to beacon node")
+	// Reset the amount.
+	atomic.StoreUint64(&v.syncCommitteeStats.totalMessagesSubmitted, 0)
+}
+
 // LogNextDutyTimeLeft logs the next duty info.
 func (v *validator) LogNextDutyTimeLeft(slot types.Slot) error {
 	if !v.logDutyCountDown {

validator/client/runner.go

@@ -260,6 +260,7 @@ func performRoles(slotCtx context.Context, allRoles map[[48]byte][]iface.Validat
 		}()
 		// Log this client performance in the previous epoch
 		v.LogAttestationsSubmitted()
+		v.LogSyncCommitteeMessagesSubmitted()
 		if err := v.LogValidatorGainsAndLosses(slotCtx, slot); err != nil {
 			log.WithError(err).Error("Could not report validator's rewards/penalties")
 		}

validator/client/service.go

@@ -196,6 +196,7 @@ func (v *ValidatorService) Start() {
 		domainDataCache:                cache,
 		aggregatedSlotCommitteeIDCache: aggregatedSlotCommitteeIDCache,
 		voteStats:                      voteStats{startEpoch: types.Epoch(^uint64(0))},
+		syncCommitteeStats:             syncCommitteeStats{},
 		useWeb:                         v.useWeb,
 		interopKeysConfig:              v.interopKeysConfig,
 		wallet:                         v.wallet,

validator/client/sync_committee.go

@@ -3,6 +3,8 @@ package client
 import (
 	"context"
 	"fmt"
+	"sync/atomic"
+	"time"
 
 	emptypb "github.com/golang/protobuf/ptypes/empty"
 	"github.com/prysmaticlabs/prysm/beacon-chain/core/altair"
@@ -77,11 +79,16 @@ func (v *validator) SubmitSyncCommitteeMessage(ctx context.Context, slot types.S
 		return
 	}
 
+	msgSlot := msg.Slot
+	slotTime := time.Unix(int64(v.genesisTime+uint64(msgSlot)*params.BeaconConfig().SecondsPerSlot), 0)
 	log.WithFields(logrus.Fields{
-		"slot":           msg.Slot,
-		"blockRoot":      fmt.Sprintf("%#x", bytesutil.Trunc(msg.BlockRoot)),
-		"validatorIndex": msg.ValidatorIndex,
+		"slot":               msg.Slot,
+		"slotStartTime":      slotTime,
+		"timeSinceSlotStart": time.Since(slotTime),
+		"blockRoot":          fmt.Sprintf("%#x", bytesutil.Trunc(msg.BlockRoot)),
+		"validatorIndex":     msg.ValidatorIndex,
 	}).Info("Submitted new sync message")
+	atomic.AddUint64(&v.syncCommitteeStats.totalMessagesSubmitted, 1)
 }
 
 // SubmitSignedContributionAndProof submits the signed sync committee contribution and proof to the beacon chain.
@@ -165,12 +172,16 @@ func (v *validator) SubmitSignedContributionAndProof(ctx context.Context, slot t
 			return
 		}
 
+		contributionSlot := contributionAndProof.Contribution.Slot
+		slotTime := time.Unix(int64(v.genesisTime+uint64(contributionSlot)*params.BeaconConfig().SecondsPerSlot), 0)
 		log.WithFields(logrus.Fields{
-			"slot":              contributionAndProof.Contribution.Slot,
-			"blockRoot":         fmt.Sprintf("%#x", bytesutil.Trunc(contributionAndProof.Contribution.BlockRoot)),
-			"subcommitteeIndex": contributionAndProof.Contribution.SubcommitteeIndex,
-			"aggregatorIndex":   contributionAndProof.AggregatorIndex,
-			"bitsCount":         contributionAndProof.Contribution.AggregationBits.Count(),
+			"slot":               contributionAndProof.Contribution.Slot,
+			"slotStartTime":      slotTime,
+			"timeSinceSlotStart": time.Since(slotTime),
+			"blockRoot":          fmt.Sprintf("%#x", bytesutil.Trunc(contributionAndProof.Contribution.BlockRoot)),
+			"subcommitteeIndex":  contributionAndProof.Contribution.SubcommitteeIndex,
+			"aggregatorIndex":    contributionAndProof.AggregatorIndex,
+			"bitsCount":          contributionAndProof.Contribution.AggregationBits.Count(),
 		}).Info("Submitted new sync contribution and proof")
 	}
 }

validator/client/testutil/mock_validator.go

@@ -69,6 +69,9 @@ func (fv *FakeValidator) WaitForKeymanagerInitialization(_ context.Context) erro
 	return nil
 }
 
+// LogSyncCommitteeMessagesSubmitted --
+func (fv *FakeValidator) LogSyncCommitteeMessagesSubmitted() {}
+
 // WaitForChainStart for mocking.
 func (fv *FakeValidator) WaitForChainStart(_ context.Context) error {
 	fv.WaitForChainStartCalled++

validator/client/validator.go

@@ -95,6 +95,7 @@ type validator struct {
 	validatorClient                    ethpb.BeaconNodeValidatorClient
 	graffiti                           []byte
 	voteStats                          voteStats
+	syncCommitteeStats                 syncCommitteeStats
 	Web3SignerConfig                   *remoteweb3signer.SetupConfig
 	ProposerSettings                   *validatorserviceconfig.ProposerSettings
 	walletIntializedChannel            chan *wallet.Wallet
@@ -1071,3 +1072,8 @@ type voteStats struct {
 	totalCorrectTarget  uint64
 	totalCorrectHead    uint64
 }
+
+// This tracks all validators' submissions for sync committees.
+type syncCommitteeStats struct {
+	totalMessagesSubmitted uint64
+}