Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Improve vc logs #13573

Merged
merged 11 commits into from
Feb 8, 2024
Merged

Improve vc logs #13573

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
11 commits
Select commit Hold shift + click to select a range
4b78dd8
duties
rkapka Feb 1, 2024
407bb2f
atts
rkapka Feb 1, 2024
aede437
revert some changes
rkapka Feb 1, 2024
3b5256d
revert timeTillDuty
rkapka Feb 2, 2024
6806ca9
Manu's review
rkapka Feb 2, 2024
af89707
Revert "Auxiliary commit to revert individual files from 6806ca9fbe18…
rkapka Feb 2, 2024
df8da78
remove trash
rkapka Feb 2, 2024
f9f30eb
more reivew
rkapka Feb 8, 2024
2b66988
making Manu happy
rkapka Feb 8, 2024
e538cc0
test fixes
rkapka Feb 8, 2024
b198f1e
Merge branch 'develop' into improve-vc-logs
rkapka Feb 8, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion validator/accounts/accounts_delete.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@ func (acm *CLIManager) Delete(ctx context.Context) error {
}); err != nil {
return err
}
log.WithField("publicKeys", allAccountStr).Warn(
log.WithField("pubkeys", allAccountStr).Warn(
"Attempted to delete accounts. IMPORTANT: please run `validator accounts list` to ensure " +
"the public keys are indeed deleted. If they are still there, please file an issue at " +
"https://github.com/prysmaticlabs/prysm/issues/new")
Expand Down
2 changes: 1 addition & 1 deletion validator/accounts/accounts_exit.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -171,7 +171,7 @@ func displayExitInfo(rawExitedKeys [][]byte, trimmedExitedKeys []string) {
info := fmt.Sprintf("Voluntary exit was successful for the accounts listed. "+
"URLs where you can track each validator's exit:\n"+strings.Repeat("%s\n", len(ifaceKeys)), ifaceKeys...)

log.WithField("publicKeys", strings.Join(trimmedExitedKeys, ", ")).Info(info)
log.WithField("pubkeys", strings.Join(trimmedExitedKeys, ", ")).Info(info)
} else {
log.Info("No successful voluntary exits")
}
Expand Down
20 changes: 10 additions & 10 deletions validator/client/attest.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -54,7 +54,7 @@ func (v *validator) SubmitAttestation(ctx context.Context, slot primitives.Slot,
defer lock.Unlock()

fmtKey := fmt.Sprintf("%#x", pubKey[:])
log := log.WithField("pubKey", fmt.Sprintf("%#x", bytesutil.Trunc(pubKey[:]))).WithField("slot", slot)
log := log.WithField("pubkey", fmt.Sprintf("%#x", bytesutil.Trunc(pubKey[:]))).WithField("slot", slot)
duty, err := v.duty(pubKey)
if err != nil {
log.WithError(err).Error("Could not fetch validator assignment")
Expand Down Expand Up @@ -293,14 +293,14 @@ func (v *validator) waitOneThirdOrValidBlock(ctx context.Context, slot primitive

func attestationLogFields(pubKey [fieldparams.BLSPubkeyLength]byte, indexedAtt *ethpb.IndexedAttestation) logrus.Fields {
return logrus.Fields{
"attesterPublicKey": fmt.Sprintf("%#x", pubKey),
"attestationSlot": indexedAtt.Data.Slot,
"committeeIndex": indexedAtt.Data.CommitteeIndex,
"beaconBlockRoot": fmt.Sprintf("%#x", indexedAtt.Data.BeaconBlockRoot),
"sourceEpoch": indexedAtt.Data.Source.Epoch,
"sourceRoot": fmt.Sprintf("%#x", indexedAtt.Data.Source.Root),
"targetEpoch": indexedAtt.Data.Target.Epoch,
"targetRoot": fmt.Sprintf("%#x", indexedAtt.Data.Target.Root),
"signature": fmt.Sprintf("%#x", indexedAtt.Signature),
"pubkey": fmt.Sprintf("%#x", pubKey),
"slot": indexedAtt.Data.Slot,
"committeeIndex": indexedAtt.Data.CommitteeIndex,
"blockRoot": fmt.Sprintf("%#x", indexedAtt.Data.BeaconBlockRoot),
"sourceEpoch": indexedAtt.Data.Source.Epoch,
"sourceRoot": fmt.Sprintf("%#x", indexedAtt.Data.Source.Root),
"targetEpoch": indexedAtt.Data.Target.Epoch,
"targetRoot": fmt.Sprintf("%#x", indexedAtt.Data.Target.Root),
"signature": fmt.Sprintf("%#x", indexedAtt.Signature),
}
}
6 changes: 3 additions & 3 deletions validator/client/log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,7 @@ import (
"github.com/sirupsen/logrus"
)

var log = logrus.WithField("prefix", "validator")
var log = logrus.WithField("prefix", "client")

type submittedAttData struct {
beaconBlockRoot []byte
Expand Down Expand Up @@ -104,7 +104,7 @@ func (v *validator) LogSubmittedAtts(slot primitives.Slot) {
"slot": slot,
"committeeIndices": committees,
"pubkeys": pubkeys,
"beaconBlockRoot": fmt.Sprintf("%#x", bytesutil.Trunc(attLog.data.beaconBlockRoot)),
"blockRoot": fmt.Sprintf("%#x", bytesutil.Trunc(attLog.data.beaconBlockRoot)),
"sourceEpoch": attLog.data.source.Epoch,
"sourceRoot": fmt.Sprintf("%#x", bytesutil.Trunc(attLog.data.source.Root)),
"targetEpoch": attLog.data.target.Epoch,
Expand All @@ -124,7 +124,7 @@ func (v *validator) LogSubmittedAtts(slot primitives.Slot) {
"slot": slot,
"committeeIndices": committees,
"pubkeys": pubkeys,
"beaconBlockRoot": fmt.Sprintf("%#x", bytesutil.Trunc(attLog.data.beaconBlockRoot)),
"blockRoot": fmt.Sprintf("%#x", bytesutil.Trunc(attLog.data.beaconBlockRoot)),
"sourceEpoch": attLog.data.source.Epoch,
"sourceRoot": fmt.Sprintf("%#x", bytesutil.Trunc(attLog.data.source.Root)),
"targetEpoch": attLog.data.target.Epoch,
Expand Down
12 changes: 6 additions & 6 deletions validator/client/metrics.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -298,25 +298,25 @@ func (v *validator) logForEachValidator(index int, pubKey []byte, resp *ethpb.Va
if index < len(resp.BalancesBeforeEpochTransition) {
balBeforeEpoch = resp.BalancesBeforeEpochTransition[index]
} else {
log.WithField("pubKey", truncatedKey).Warn("Missing balance before epoch transition")
log.WithField("pubkey", truncatedKey).Warn("Missing balance before epoch transition")
}
if index < len(resp.BalancesAfterEpochTransition) {
balAfterEpoch = resp.BalancesAfterEpochTransition[index]
}
if index < len(resp.CorrectlyVotedSource) {
correctlyVotedSource = resp.CorrectlyVotedSource[index]
} else {
log.WithField("pubKey", truncatedKey).Warn("Missing correctly voted source")
log.WithField("pubkey", truncatedKey).Warn("Missing correctly voted source")
}
if index < len(resp.CorrectlyVotedTarget) {
correctlyVotedTarget = resp.CorrectlyVotedTarget[index]
} else {
log.WithField("pubKey", truncatedKey).Warn("Missing correctly voted target")
log.WithField("pubkey", truncatedKey).Warn("Missing correctly voted target")
}
if index < len(resp.CorrectlyVotedHead) {
correctlyVotedHead = resp.CorrectlyVotedHead[index]
} else {
log.WithField("pubKey", truncatedKey).Warn("Missing correctly voted head")
log.WithField("pubkey", truncatedKey).Warn("Missing correctly voted head")
}

if _, ok := v.startBalances[pubKeyBytes]; !ok {
Expand All @@ -333,7 +333,7 @@ func (v *validator) logForEachValidator(index int, pubKey []byte, resp *ethpb.Va
percentSinceStart := (newBalance - startBalance) / startBalance

previousEpochSummaryFields := logrus.Fields{
"pubKey": truncatedKey,
"pubkey": truncatedKey,
"epoch": prevEpoch,
"correctlyVotedSource": correctlyVotedSource,
"correctlyVotedTarget": correctlyVotedTarget,
Expand All @@ -349,7 +349,7 @@ func (v *validator) logForEachValidator(index int, pubKey []byte, resp *ethpb.Va
if index < len(resp.InactivityScores) {
previousEpochSummaryFields["inactivityScore"] = resp.InactivityScores[index]
} else {
log.WithField("pubKey", truncatedKey).Warn("Missing inactivity score")
log.WithField("pubkey", truncatedKey).Warn("Missing inactivity score")
}
}

Expand Down
18 changes: 9 additions & 9 deletions validator/client/propose.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@ func (v *validator) ProposeBlock(ctx context.Context, slot primitives.Slot, pubK

fmtKey := fmt.Sprintf("%#x", pubKey[:])
span.AddAttributes(trace.StringAttribute("validator", fmtKey))
log := log.WithField("pubKey", fmt.Sprintf("%#x", bytesutil.Trunc(pubKey[:])))
log := log.WithField("pubkey", fmt.Sprintf("%#x", bytesutil.Trunc(pubKey[:])))

// Sign randao reveal, it's used to request block from beacon node
epoch := primitives.Epoch(slot / params.BeaconConfig().SlotsPerEpoch)
Expand Down Expand Up @@ -79,7 +79,7 @@ func (v *validator) ProposeBlock(ctx context.Context, slot primitives.Slot, pubK
Graffiti: g,
})
if err != nil {
log.WithField("blockSlot", slot).WithError(err).Error("Failed to request block from beacon node")
log.WithField("slot", slot).WithError(err).Error("Failed to request block from beacon node")
if v.emitAccountMetrics {
ValidatorProposeFailVec.WithLabelValues(fmtKey).Inc()
}
Expand Down Expand Up @@ -150,7 +150,7 @@ func (v *validator) ProposeBlock(ctx context.Context, slot primitives.Slot, pubK

blkResp, err := v.validatorClient.ProposeBeaconBlock(ctx, genericSignedBlock)
if err != nil {
log.WithField("blockSlot", slot).WithError(err).Error("Failed to propose block")
log.WithField("slot", slot).WithError(err).Error("Failed to propose block")
if v.emitAccountMetrics {
ValidatorProposeFailVec.WithLabelValues(fmtKey).Inc()
}
Expand Down Expand Up @@ -207,12 +207,12 @@ func (v *validator) ProposeBlock(ctx context.Context, slot primitives.Slot, pubK
blkRoot := fmt.Sprintf("%#x", bytesutil.Trunc(blkResp.BlockRoot))
graffiti := blk.Block().Body().Graffiti()
log.WithFields(logrus.Fields{
"slot": blk.Block().Slot(),
"blockRoot": blkRoot,
"numAttestations": len(blk.Block().Body().Attestations()),
"numDeposits": len(blk.Block().Body().Deposits()),
"graffiti": string(graffiti[:]),
"fork": version.String(blk.Block().Version()),
"slot": blk.Block().Slot(),
"blockRoot": blkRoot,
"attestationCount": len(blk.Block().Body().Attestations()),
"depositCount": len(blk.Block().Body().Deposits()),
"graffiti": string(graffiti[:]),
"fork": version.String(blk.Block().Version()),
}).Info("Submitted new block")

if v.emitAccountMetrics {
Expand Down
6 changes: 3 additions & 3 deletions validator/client/propose_protect.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -89,9 +89,9 @@ func (v *validator) slashableProposalCheck(

func blockLogFields(pubKey [fieldparams.BLSPubkeyLength]byte, blk interfaces.ReadOnlyBeaconBlock, sig []byte) logrus.Fields {
fields := logrus.Fields{
"proposerPublicKey": fmt.Sprintf("%#x", pubKey),
"proposerIndex": blk.ProposerIndex(),
"blockSlot": blk.Slot(),
"pubkey": fmt.Sprintf("%#x", pubKey),
"proposerIndex": blk.ProposerIndex(),
"slot": blk.Slot(),
}
if sig != nil {
fields["signature"] = fmt.Sprintf("%#x", sig)
Expand Down
6 changes: 3 additions & 3 deletions validator/client/runner.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -244,7 +244,7 @@ func performRoles(slotCtx context.Context, allRoles map[[48]byte][]iface.Validat
case iface.RoleSyncCommitteeAggregator:
v.SubmitSignedContributionAndProof(slotCtx, slot, pubKey)
case iface.RoleUnknown:
log.WithField("pubKey", fmt.Sprintf("%#x", bytesutil.Trunc(pubKey[:]))).Trace("No active roles, doing nothing")
log.WithField("pubkey", fmt.Sprintf("%#x", bytesutil.Trunc(pubKey[:]))).Trace("No active roles, doing nothing")
default:
log.Warnf("Unhandled role %v", role)
}
Expand All @@ -258,7 +258,7 @@ func performRoles(slotCtx context.Context, allRoles map[[48]byte][]iface.Validat
defer span.End()
defer func() {
if err := recover(); err != nil { // catch any panic in logging
log.WithField("err", err).
log.WithField("error", err).
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can't use WithError because err is of type any

Error("Panic occurred when logging validator report. This" +
" should never happen! Please file a report at github.com/prysmaticlabs/prysm/issues/new")
}
Expand All @@ -284,7 +284,7 @@ func handleAssignmentError(err error, slot primitives.Slot) {
"epoch", slot/params.BeaconConfig().SlotsPerEpoch,
).Warn("Validator not yet assigned to epoch")
} else {
log.WithField("error", err).Error("Failed to update assignments")
log.WithError(err).Error("Failed to update assignments")
}
}

Expand Down
28 changes: 14 additions & 14 deletions validator/client/validator.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -360,11 +360,11 @@ func (v *validator) checkAndLogValidatorStatus(statuses []*validatorStatus, acti
var validatorActivated bool
for _, status := range statuses {
fields := logrus.Fields{
"pubKey": fmt.Sprintf("%#x", bytesutil.Trunc(status.publicKey)),
"pubkey": fmt.Sprintf("%#x", bytesutil.Trunc(status.publicKey)),
"status": status.status.Status.String(),
}
if status.index != nonexistentIndex {
fields["index"] = status.index
fields["validatorIndex"] = status.index
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We have validatorIndex in other places. I prefer this way rather than index because it might be unclear what kind of index it is (maybe not in this exact place, but somewhere else).

}
log := log.WithFields(fields)
if v.emitAccountMetrics {
Expand Down Expand Up @@ -447,7 +447,7 @@ func (v *validator) CheckDoppelGanger(ctx context.Context) error {
if err != nil {
return err
}
log.WithField("keys", len(pubkeys)).Info("Running doppelganger check")
log.WithField("keyCount", len(pubkeys)).Info("Running doppelganger check")
// Exit early if no validating pub keys are found.
if len(pubkeys) == 0 {
return nil
Expand Down Expand Up @@ -562,7 +562,7 @@ func (v *validator) UpdateDuties(ctx context.Context, slot primitives.Slot) erro
filteredKeys = append(filteredKeys, pubKey)
} else {
log.WithField(
"publicKey", fmt.Sprintf("%#x", bytesutil.Trunc(pubKey[:])),
"pubkey", fmt.Sprintf("%#x", bytesutil.Trunc(pubKey[:])),
).Warn("Not including slashable public key from slashing protection import " +
"in request to update validator duties")
}
Expand Down Expand Up @@ -967,14 +967,14 @@ func (v *validator) logDuties(slot primitives.Slot, currentEpochDuties []*ethpb.
isAttester := len(attesterKeys[i]) > 0
if isAttester {
slotLog = slotLog.WithFields(logrus.Fields{
"slot": epochStartSlot + i,
"slotInEpoch": (epochStartSlot + i) % params.BeaconConfig().SlotsPerEpoch,
"attesterCount": len(attesterKeys[i]),
"pubkeys": attesterKeys[i],
"slot": epochStartSlot + i,
"slotInEpoch": (epochStartSlot + i) % params.BeaconConfig().SlotsPerEpoch,
"attesterCount": len(attesterKeys[i]),
"attesterPubkeys": attesterKeys[i],
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we have a proposerPubkey field too, so can't use pubkeys

})
}
if durationTillDuty > 0 {
slotLog = slotLog.WithField("timeTillDuty", durationTillDuty)
slotLog = slotLog.WithField("timeUntilDuty", durationTillDuty)
}
if isProposer || isAttester {
slotLog.Infof("Duties schedule")
Expand Down Expand Up @@ -1030,8 +1030,8 @@ func (v *validator) PushProposerSettings(ctx context.Context, km keymanager.IKey
}
if len(proposerReqs) != len(pubkeys) {
log.WithFields(logrus.Fields{
"pubkeysCount": len(pubkeys),
"proposerSettingsReqCount": len(proposerReqs),
"pubkeysCount": len(pubkeys),
"proposerSettingsRequestCount": len(proposerReqs),
}).Debugln("Request count did not match included validator count. Only keys that have been activated will be included in the request.")
}
if _, err := v.validatorClient.PrepareBeaconProposer(ctx, &ethpb.PrepareBeaconProposerRequest{
Expand Down Expand Up @@ -1095,9 +1095,9 @@ func (v *validator) filterAndCacheActiveKeys(ctx context.Context, pubkeys [][fie
filteredKeys = append(filteredKeys, bytesutil.ToBytes48(resp.PublicKeys[i]))
} else {
log.WithFields(logrus.Fields{
"publickey": hexutil.Encode(resp.PublicKeys[i]),
"status": status.Status.String(),
}).Debugf("skipping non active status key.")
"pubkey": hexutil.Encode(resp.PublicKeys[i]),
"status": status.Status.String(),
}).Debugf("Skipping non-active status key.")
}
}

Expand Down
4 changes: 2 additions & 2 deletions validator/db/kv/attester_protection.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -354,7 +354,7 @@ func (s *Store) batchAttestationWrites(ctx context.Context) {
span.AddAttributes(trace.Int64Attribute("num_records", int64(s.batchedAttestations.Len())))

if numRecords := s.batchedAttestations.Len(); numRecords >= attestationBatchCapacity {
log.WithField("numRecords", numRecords).Debug(
log.WithField("recordCount", numRecords).Debug(
"Reached max capacity of batched attestation records, flushing to DB",
)
if s.batchedAttestationsFlushInProgress.IsNotSet() {
Expand All @@ -368,7 +368,7 @@ func (s *Store) batchAttestationWrites(ctx context.Context) {
span.End()
case <-ticker.C:
if numRecords := s.batchedAttestations.Len(); numRecords > 0 {
log.WithField("numRecords", numRecords).Debug(
log.WithField("recordCount", numRecords).Debug(
"Batched attestation records write interval reached, flushing to DB",
)
if s.batchedAttestationsFlushInProgress.IsNotSet() {
Expand Down
2 changes: 1 addition & 1 deletion validator/keymanager/local/import.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -91,7 +91,7 @@ func (km *Keymanager) ImportKeystores(
}

log.WithFields(logrus.Fields{
"publicKeys": CreatePrintoutOfKeys(importedKeys),
"pubkeys": CreatePrintoutOfKeys(importedKeys),
}).Info("Successfully imported validator key(s)")

// 5) Return Statuses
Expand Down
2 changes: 1 addition & 1 deletion validator/keymanager/remote-web3signer/internal/log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,4 +4,4 @@ import (
"github.com/sirupsen/logrus"
)

var log = logrus.WithField("prefix", "remote_web3signer_internal")
var log = logrus.WithField("prefix", "remote-web3signer-internal")
2 changes: 1 addition & 1 deletion validator/node/node.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -831,7 +831,7 @@ func (c *ValidatorClient) registerRPCService(router *mux.Router) error {
func (c *ValidatorClient) registerRPCGatewayService(router *mux.Router) error {
gatewayHost := c.cliCtx.String(flags.GRPCGatewayHost.Name)
if gatewayHost != flags.DefaultGatewayHost {
log.WithField("web-host", gatewayHost).Warn(
log.WithField("webHost", gatewayHost).Warn(
"You are using a non-default web host. Web traffic is served by HTTP, so be wary of " +
"changing this parameter if you are exposing this host to the Internet!",
)
Expand Down
4 changes: 2 additions & 2 deletions validator/rpc/server.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -170,8 +170,8 @@ func (s *Server) Start() {
}
opts = append(opts, grpc.Creds(creds))
log.WithFields(logrus.Fields{
"crt-path": s.withCert,
"key-path": s.withKey,
"certPath": s.withCert,
"keyPath": s.withKey,
}).Info("Loaded TLS certificates")
}
s.grpcServer = grpc.NewServer(opts...)
Expand Down
2 changes: 1 addition & 1 deletion validator/web/log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,4 +2,4 @@ package web

import "github.com/sirupsen/logrus"

var log = logrus.WithField("prefix", "prysm-web")
var log = logrus.WithField("prefix", "web")
Loading