From 2eff8704a5261efcd6a8024dbe4fa53a9b550d7c Mon Sep 17 00:00:00 2001 From: Ivan Martinez Date: Wed, 3 Jun 2020 19:12:18 -0400 Subject: [PATCH] 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 | 66 ++++++++++++++------------- validator/accounts/status_test.go | 4 +- validator/client/validator.go | 35 ++++++++------ validator/client/validator_metrics.go | 1 - validator/client/validator_test.go | 26 +++++++---- 5 files changed, 76 insertions(+), 56 deletions(-) diff --git a/validator/accounts/status.go b/validator/accounts/status.go index 65387586b4..0f9ac28f4a 100644 --- a/validator/accounts/status.go +++ b/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 := ðpb.MultipleValidatorStatusRequest{PublicKeys: pubkeys} - resp, err := beaconNodeRPCProvider.MultipleValidatorStatus(ctx, req) + req := ðpb.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) -} diff --git a/validator/accounts/status_test.go b/validator/accounts/status_test.go index 31d777e849..4da2731822 100644 --- a/validator/accounts/status_test.go +++ b/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(), ðpb.MultipleValidatorStatusRequest{PublicKeys: pubkeys}, - ) + ).Return(ðpb.MultipleValidatorStatusResponse{PublicKeys: pubkeys, Indices: indices}, nil /*err*/) _, err := FetchAccountStatuses(ctx, mockClient, pubkeys) if err != nil { t.Fatalf("FetchAccountStatuses failed with error: %v.", err) diff --git a/validator/client/validator.go b/validator/client/validator.go index 280c576066..64a045f266 100644 --- a/validator/client/validator.go +++ b/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 diff --git a/validator/client/validator_metrics.go b/validator/client/validator_metrics.go index 463276605d..477d5e7b44 100644 --- a/validator/client/validator_metrics.go +++ b/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) } diff --git a/validator/client/validator_test.go b/validator/client/validator_test.go index fe63718e1e..888cd64ba9 100644 --- a/validator/client/validator_test.go +++ b/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: ðpb.ValidatorActivationResponse_Status{ PublicKey: pubKeys[0], + Index: nonexistentIndex, Status: ðpb.ValidatorStatusResponse{ Status: ethpb.ValidatorStatus_UNKNOWN_STATUS, }, @@ -957,6 +959,7 @@ func TestCheckAndLogValidatorStatus_OK(t *testing.T) { name: "DEPOSITED, deposit found", status: ðpb.ValidatorActivationResponse_Status{ PublicKey: pubKeys[0], + Index: nonexistentIndex, Status: ðpb.ValidatorStatusResponse{ Status: ethpb.ValidatorStatus_DEPOSITED, DepositInclusionSlot: 50, @@ -969,36 +972,39 @@ func TestCheckAndLogValidatorStatus_OK(t *testing.T) { name: "DEPOSITED into state", status: ðpb.ValidatorActivationResponse_Status{ PublicKey: pubKeys[0], + Index: 30, Status: ðpb.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: ðpb.ValidatorActivationResponse_Status{ PublicKey: pubKeys[0], + Index: 50, Status: ðpb.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: ðpb.ValidatorActivationResponse_Status{ PublicKey: pubKeys[0], + Index: 89, Status: ðpb.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)