Add indice to certain validator logs (#6092)

* Add indice to activation and accounts list command

* Add to more logs

* Fix wrong !

* Fix err

* Fix tests

validator/accounts/status.go

@@ -2,13 +2,13 @@ package accounts
 
 import (
 	"context"
-	"encoding/hex"
 	"fmt"
 	"sort"
 	"time"
 
 	"github.com/pkg/errors"
 	ethpb "github.com/prysmaticlabs/ethereumapis/eth/v1alpha1"
+	"github.com/prysmaticlabs/prysm/shared/params"
 	"github.com/sirupsen/logrus"
 	"go.opencensus.io/trace"
 )
@@ -16,16 +16,15 @@ import (
 // ValidatorStatusMetadata holds all status information about a validator.
 type ValidatorStatusMetadata struct {
 	PublicKey []byte
+	Index     uint64
 	Metadata  *ethpb.ValidatorStatusResponse
 }
 
 // RunStatusCommand is the entry point to the `validator status` command.
-func RunStatusCommand(
-	pubkeys [][]byte, beaconNodeRPCProvider ethpb.BeaconNodeValidatorClient) error {
-	statuses, err := FetchAccountStatuses(
-		context.Background(), beaconNodeRPCProvider, pubkeys)
+func RunStatusCommand(pubKeys [][]byte, beaconNodeRPCProvider ethpb.BeaconNodeValidatorClient) error {
+	statuses, err := FetchAccountStatuses(context.Background(), beaconNodeRPCProvider, pubKeys)
 	if err != nil {
-		return errors.Wrap(err, "Could not fetch account statuses from the beacon node")
+		return errors.Wrap(err, "could not fetch account statuses from the beacon node")
 	}
 	printStatuses(statuses)
 	return nil
@@ -35,24 +34,25 @@ func RunStatusCommand(
 // for each validator public key.
 func FetchAccountStatuses(
 	ctx context.Context,
-	beaconNodeRPCProvider ethpb.BeaconNodeValidatorClient,
-	pubkeys [][]byte) ([]ValidatorStatusMetadata, error) {
+	beaconClient ethpb.BeaconNodeValidatorClient,
+	pubKeys [][]byte,
+) ([]ValidatorStatusMetadata, error) {
 	ctx, span := trace.StartSpan(ctx, "accounts.FetchAccountStatuses")
 	defer span.End()
 	ctx, cancel := context.WithTimeout(ctx, 30*time.Second /* Cancel if running over thirty seconds. */)
 	defer cancel()
 
-	req := &ethpb.MultipleValidatorStatusRequest{PublicKeys: pubkeys}
-	resp, err := beaconNodeRPCProvider.MultipleValidatorStatus(ctx, req)
+	req := &ethpb.MultipleValidatorStatusRequest{PublicKeys: pubKeys}
+	resp, err := beaconClient.MultipleValidatorStatus(ctx, req)
 	if err != nil {
 		return nil, err
 	}
 
-	respKeys := resp.GetPublicKeys()
-	statuses := make([]ValidatorStatusMetadata, len(respKeys))
-	for i, status := range resp.GetStatuses() {
+	statuses := make([]ValidatorStatusMetadata, len(resp.Statuses))
+	for i, status := range resp.Statuses {
 		statuses[i] = ValidatorStatusMetadata{
-			PublicKey: respKeys[i],
+			PublicKey: resp.PublicKeys[i],
+			Index:     resp.Indices[i],
 			Metadata:  status,
 		}
 	}
@@ -64,25 +64,29 @@ func FetchAccountStatuses(
 }
 
 func printStatuses(validatorStatuses []ValidatorStatusMetadata) {
+	nonexistentIndex := ^uint64(0)
 	for _, v := range validatorStatuses {
 		m := v.Metadata
 		key := v.PublicKey
-		log.WithFields(
-			logrus.Fields{
-				"PublicKey":                 hex.EncodeToString(key),
-				"ActivationEpoch":           fieldToString(m.ActivationEpoch),
-				"DepositInclusionSlot":      fieldToString(m.DepositInclusionSlot),
-				"Eth1DepositBlockNumber":    fieldToString(m.Eth1DepositBlockNumber),
-				"PositionInActivationQueue": fieldToString(m.PositionInActivationQueue),
-			},
-		).Infof("Status: %s", m.Status.String())
+		fields := logrus.Fields{
+			"publicKey": fmt.Sprintf("%#x", key),
+		}
+		if v.Index != nonexistentIndex {
+			fields["index"] = v.Index
+		}
+		if m.Status == ethpb.ValidatorStatus_PENDING || m.Status == ethpb.ValidatorStatus_ACTIVE {
+			fields["activationEpoch"] = m.ActivationEpoch
+			if m.ActivationEpoch == params.BeaconConfig().FarFutureEpoch {
+				fields["positionInActivationQueue"] = m.PositionInActivationQueue
+			}
+		} else if m.Status == ethpb.ValidatorStatus_DEPOSITED {
+			if m.PositionInActivationQueue != 0 {
+				fields["depositInclusionSlot"] = m.DepositInclusionSlot
+				fields["eth1DepositBlockNumber"] = m.Eth1DepositBlockNumber
+			} else {
+				fields["positionInActivationQueue"] = m.PositionInActivationQueue
+			}
+		}
+		log.WithFields(fields).Infof("Status: %s", m.Status.String())
 	}
 }
-
-func fieldToString(field uint64) string {
-	// Field is missing
-	if field == 0 {
-		return "NA"
-	}
-	return fmt.Sprintf("%d", field)
-}

validator/accounts/status_test.go

@@ -14,15 +14,17 @@ func TestFetchAccountStatuses_OK(t *testing.T) {
 	ctrl := gomock.NewController(t)
 	defer ctrl.Finish()
 	pubkeys := make([][]byte, 10000)
+	indices := make([]uint64, 10000)
 	for i := 0; i < 10000; i++ {
 		pubkeys[i] = []byte{byte(i)}
+		indices[i] = uint64(i)
 	}
 
 	mockClient := mock.NewMockBeaconNodeValidatorClient(ctrl)
 	mockClient.EXPECT().MultipleValidatorStatus(
 		gomock.Any(),
 		&ethpb.MultipleValidatorStatusRequest{PublicKeys: pubkeys},
-	)
+	).Return(&ethpb.MultipleValidatorStatusResponse{PublicKeys: pubkeys, Indices: indices}, nil /*err*/)
 	_, err := FetchAccountStatuses(ctx, mockClient, pubkeys)
 	if err != nil {
 		t.Fatalf("FetchAccountStatuses failed with error: %v.", err)

validator/client/validator.go

@@ -202,7 +202,6 @@ func (v *validator) WaitForActivation(ctx context.Context) error {
 	if err != nil {
 		return errors.Wrap(err, "could not setup validator WaitForActivation streaming client")
 	}
-	var validatorActivatedRecords [][]byte
 	for {
 		res, err := stream.Recv()
 		// If the stream is closed, we stop the loop.
@@ -216,28 +215,38 @@ func (v *validator) WaitForActivation(ctx context.Context) error {
 		if err != nil {
 			return errors.Wrap(err, "could not receive validator activation from stream")
 		}
-		activatedKeys := v.checkAndLogValidatorStatus(res.Statuses)
+		valActivated := v.checkAndLogValidatorStatus(res.Statuses)
 
-		if len(activatedKeys) > 0 {
-			validatorActivatedRecords = activatedKeys
+		if valActivated {
+			for _, statusResp := range res.Statuses {
+				if statusResp.Status.Status != ethpb.ValidatorStatus_ACTIVE {
+					continue
+				}
+				log.WithFields(logrus.Fields{
+					"publicKey": fmt.Sprintf("%#x", bytesutil.Trunc(statusResp.PublicKey)),
+					"index":     statusResp.Index,
+				}).Info("Validator activated")
+			}
 			break
 		}
 	}
-	for _, pubKey := range validatorActivatedRecords {
-		log.WithField("pubKey", fmt.Sprintf("%#x", bytesutil.Trunc(pubKey[:]))).Info("Validator activated")
-	}
 	v.ticker = slotutil.GetSlotTicker(time.Unix(int64(v.genesisTime), 0), params.BeaconConfig().SecondsPerSlot)
 
 	return nil
 }
 
-func (v *validator) checkAndLogValidatorStatus(validatorStatuses []*ethpb.ValidatorActivationResponse_Status) [][]byte {
-	var activatedKeys [][]byte
+func (v *validator) checkAndLogValidatorStatus(validatorStatuses []*ethpb.ValidatorActivationResponse_Status) bool {
+	nonexistentIndex := ^uint64(0)
+	var validatorActivated bool
 	for _, status := range validatorStatuses {
-		log := log.WithFields(logrus.Fields{
+		fields := logrus.Fields{
 			"pubKey": fmt.Sprintf("%#x", bytesutil.Trunc(status.PublicKey[:])),
 			"status": status.Status.Status.String(),
-		})
+		}
+		if status.Index != nonexistentIndex {
+			fields["index"] = status.Index
+		}
+		log := log.WithFields(fields)
 		if v.emitAccountMetrics {
 			fmtKey := fmt.Sprintf("%#x", status.PublicKey)
 			validatorStatusesGaugeVec.WithLabelValues(fmtKey).Set(float64(status.Status.Status))
@@ -267,7 +276,7 @@ func (v *validator) checkAndLogValidatorStatus(validatorStatuses []*ethpb.Valida
 				}).Info("Waiting for activation")
 			}
 		case ethpb.ValidatorStatus_ACTIVE:
-			activatedKeys = append(activatedKeys, status.PublicKey)
+			validatorActivated = true
 		case ethpb.ValidatorStatus_EXITED:
 			log.Info("Validator exited")
 		default:
@@ -276,7 +285,7 @@ func (v *validator) checkAndLogValidatorStatus(validatorStatuses []*ethpb.Valida
 			}).Info("Validator status")
 		}
 	}
-	return activatedKeys
+	return validatorActivated
 }
 
 // CanonicalHeadSlot returns the slot of canonical block currently found in the

validator/client/validator_metrics.go

@@ -67,7 +67,6 @@ func (v *validator) LogValidatorGainsAndLosses(ctx context.Context, slot uint64)
 		log := log.WithField("pubKey", pubKey)
 		fmtKey := fmt.Sprintf("%#x", pkey[:])
 		if missingValidators[bytesutil.ToBytes48(pkey)] {
-			log.Info("Validator not in beacon chain")
 			if v.emitAccountMetrics {
 				validatorBalancesGaugeVec.WithLabelValues(fmtKey).Set(0)
 			}

validator/client/validator_test.go

@@ -930,11 +930,12 @@ func TestRolesAt_DoesNotAssignProposer_Slot0(t *testing.T) {
 }
 
 func TestCheckAndLogValidatorStatus_OK(t *testing.T) {
+	nonexistentIndex := ^uint64(0)
 	type statusTest struct {
-		name       string
-		status     *ethpb.ValidatorActivationResponse_Status
-		log        string
-		activeKeys [][]byte
+		name   string
+		status *ethpb.ValidatorActivationResponse_Status
+		log    string
+		active bool
 	}
 	pubKeys := [][]byte{
 		bytesutil.Uint64ToBytes(0),
@@ -947,6 +948,7 @@ func TestCheckAndLogValidatorStatus_OK(t *testing.T) {
 			name: "UNKNOWN_STATUS, no deposit found yet",
 			status: &ethpb.ValidatorActivationResponse_Status{
 				PublicKey: pubKeys[0],
+				Index:     nonexistentIndex,
 				Status: &ethpb.ValidatorStatusResponse{
 					Status: ethpb.ValidatorStatus_UNKNOWN_STATUS,
 				},
@@ -957,6 +959,7 @@ func TestCheckAndLogValidatorStatus_OK(t *testing.T) {
 			name: "DEPOSITED, deposit found",
 			status: &ethpb.ValidatorActivationResponse_Status{
 				PublicKey: pubKeys[0],
+				Index:     nonexistentIndex,
 				Status: &ethpb.ValidatorStatusResponse{
 					Status:                 ethpb.ValidatorStatus_DEPOSITED,
 					DepositInclusionSlot:   50,
@@ -969,36 +972,39 @@ func TestCheckAndLogValidatorStatus_OK(t *testing.T) {
 			name: "DEPOSITED into state",
 			status: &ethpb.ValidatorActivationResponse_Status{
 				PublicKey: pubKeys[0],
+				Index:     30,
 				Status: &ethpb.ValidatorStatusResponse{
 					Status:                    ethpb.ValidatorStatus_DEPOSITED,
 					PositionInActivationQueue: 30,
 				},
 			},
-			log: "Deposit processed, entering activation queue after finalization\" positionInActivationQueue=30",
+			log: "Deposit processed, entering activation queue after finalization\" index=30 positionInActivationQueue=30",
 		},
 		{
 			name: "PENDING",
 			status: &ethpb.ValidatorActivationResponse_Status{
 				PublicKey: pubKeys[0],
+				Index:     50,
 				Status: &ethpb.ValidatorStatusResponse{
 					Status:                    ethpb.ValidatorStatus_PENDING,
 					ActivationEpoch:           params.BeaconConfig().FarFutureEpoch,
 					PositionInActivationQueue: 6,
 				},
 			},
-			log: "Waiting to be assigned activation epoch\" positionInActivationQueue=6",
+			log: "Waiting to be assigned activation epoch\" index=50 positionInActivationQueue=6",
 		},
 		{
 			name: "PENDING",
 			status: &ethpb.ValidatorActivationResponse_Status{
 				PublicKey: pubKeys[0],
+				Index:     89,
 				Status: &ethpb.ValidatorStatusResponse{
 					Status:                    ethpb.ValidatorStatus_PENDING,
 					ActivationEpoch:           60,
 					PositionInActivationQueue: 5,
 				},
 			},
-			log: "Waiting for activation\" activationEpoch=60",
+			log: "Waiting for activation\" activationEpoch=60 index=89",
 		},
 		{
 			name: "EXITED",
@@ -1029,9 +1035,9 @@ func TestCheckAndLogValidatorStatus_OK(t *testing.T) {
 				},
 			}
 
-			activeKeys := v.checkAndLogValidatorStatus([]*ethpb.ValidatorActivationResponse_Status{test.status})
-			if !reflect.DeepEqual(activeKeys, test.activeKeys) {
-				t.Fatal("expected active keys to be equal")
+			active := v.checkAndLogValidatorStatus([]*ethpb.ValidatorActivationResponse_Status{test.status})
+			if active != test.active {
+				t.Fatalf("expected key to be active, expected %t, received %t", test.active, active)
 			}
 
 			testutil.AssertLogsContain(t, hook, test.log)