core: improve logging (#1187)

Use common prefix for all logging of each component: - bcast: "Successfully submitted ..." - parsigdb: "Partial signed data ..." - qbft: "QBFT ..." - sigagg: "Threshold aggregated ..." Also: - Sort attester duty logs by slot - Remove noisy fields - Remove noisy router debug logs category: misc ticket: none
ObolNetwork · Sep 28, 2022 · 77f3497 · 77f3497
1 parent 3383d66
commit 77f3497
Show file tree

Hide file tree

Showing 7 changed files with 34 additions and 33 deletions.
diff --git a/core/bcast/bcast.go b/core/bcast/bcast.go
@@ -76,7 +76,7 @@ func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty, pubkey core.
 			err = nil
 		}
 		if err == nil {
-			log.Info(ctx, "Attestation successfully submitted to beacon node",
+			log.Info(ctx, "Successfully submitted attestation to beacon node",
 				z.Any("delay", b.delayFunc(duty.Slot)),
 			)
 		}
@@ -90,7 +90,7 @@ func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty, pubkey core.
 
 		err = b.eth2Cl.SubmitBeaconBlock(ctx, &block.VersionedSignedBeaconBlock)
 		if err == nil {
-			log.Info(ctx, "Block proposal successfully submitted to beacon node",
+			log.Info(ctx, "Successfully submitted block proposal to beacon node",
 				z.Any("delay", b.delayFunc(duty.Slot)),
 			)
 		}
@@ -105,7 +105,7 @@ func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty, pubkey core.
 
 		err = b.eth2Cl.SubmitBlindedBeaconBlock(ctx, &block.VersionedSignedBlindedBeaconBlock)
 		if err == nil {
-			log.Info(ctx, "Blinded block proposal successfully submitted to beacon node",
+			log.Info(ctx, "Successfully submitted blinded block proposal to beacon node",
 				z.Any("delay", b.delayFunc(duty.Slot)),
 			)
 		}
@@ -120,7 +120,7 @@ func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty, pubkey core.
 
 		err = b.eth2Cl.SubmitValidatorRegistrations(ctx, []*eth2api.VersionedSignedValidatorRegistration{&registration.VersionedSignedValidatorRegistration})
 		if err == nil {
-			log.Info(ctx, "Validator registration successfully submitted to beacon node",
+			log.Info(ctx, "Successfully submitted validator registration to beacon node",
 				z.Any("delay", b.delayFunc(duty.Slot)),
 			)
 		}
@@ -135,7 +135,7 @@ func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty, pubkey core.
 
 		err = b.eth2Cl.SubmitVoluntaryExit(ctx, &exit.SignedVoluntaryExit)
 		if err == nil {
-			log.Info(ctx, "Voluntary exit successfully submitted to beacon node",
+			log.Info(ctx, "Successfully submitted voluntary exit to beacon node",
 				z.Any("delay", b.delayFunc(duty.Slot)),
 			)
 		}
@@ -155,27 +155,25 @@ func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty, pubkey core.
 			return nil
 		}
 
-		log.Debug(ctx, "V2 submit beacon committee subscriptions failed")
+		// Ignore error as beacon node probably doesn't support v2 SubmitBeaconCommitteeSubscriptions
+		// endpoint (yet). Just try again with v1.
 
-		// Beacon node doesn't support v2 SubmitBeaconCommitteeSubscriptions endpoint (yet). Try with v1.
 		res, err := eth2exp.CalculateCommitteeSubscriptionResponse(ctx, b.eth2Cl, &sub.BeaconCommitteeSubscription)
 		if err != nil {
 			return err
 		}
 
-		subs := []*eth2v1.BeaconCommitteeSubscription{
-			{
-				ValidatorIndex:   res.ValidatorIndex,
-				Slot:             res.Slot,
-				CommitteeIndex:   res.CommitteeIndex,
-				CommitteesAtSlot: res.CommitteesAtSlot,
-				IsAggregator:     res.IsAggregator,
-			},
-		}
+		subs := []*eth2v1.BeaconCommitteeSubscription{{
+			ValidatorIndex:   res.ValidatorIndex,
+			Slot:             res.Slot,
+			CommitteeIndex:   res.CommitteeIndex,
+			CommitteesAtSlot: res.CommitteesAtSlot,
+			IsAggregator:     res.IsAggregator,
+		}}
 
 		err = b.eth2Cl.SubmitBeaconCommitteeSubscriptions(ctx, subs)
 		if err == nil {
-			log.Info(ctx, "Beacon committee subscription successfully submitted to beacon node",
+			log.Info(ctx, "Successfully submitted beacon committee subscription to beacon node",
 				z.Any("delay", b.delayFunc(duty.Slot)))
 		}
 
@@ -188,7 +186,7 @@ func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty, pubkey core.
 
 		err = b.eth2Cl.SubmitAggregateAttestations(ctx, []*eth2p0.SignedAggregateAndProof{&aggAndProof.SignedAggregateAndProof})
 		if err == nil {
-			log.Info(ctx, "Attestation aggregation successfully submitted to beacon node",
+			log.Info(ctx, "Successfully submitted attestation aggregation to beacon node",
 				z.Any("delay", b.delayFunc(duty.Slot)))
 		}
 

diff --git a/core/consensus/component.go b/core/consensus/component.go
@@ -167,7 +167,7 @@ func (c *Component) Propose(ctx context.Context, duty core.Duty, data core.Unsig
 		return nil
 	}
 
-	log.Debug(ctx, "Starting qbft consensus instance", z.Any("duty", duty))
+	log.Debug(ctx, "QBFT consensus instance starting", z.Any("duty", duty))
 
 	// Hash the proposed data, since qbft ony supports simple comparable values.
 	value, err := core.UnsignedDataSetToProto(data)

diff --git a/core/fetcher/fetcher.go b/core/fetcher/fetcher.go
@@ -169,7 +169,7 @@ func (f *Fetcher) fetchAggregatorData(ctx context.Context, slot int64, defSet co
 
 		// This validator isn't an aggregator for this slot.
 		if !res.IsAggregator {
-			log.Debug(ctx, "Not selected for attester aggregation duty", z.Any("pubkey", pubkey))
+			log.Debug(ctx, "Attester not selected for aggregation duty", z.Any("pubkey", pubkey))
 			continue
 		}
 		log.Info(ctx, "Resolved attester aggregation duty", z.Any("pubkey", pubkey))

diff --git a/core/parsigdb/memory.go b/core/parsigdb/memory.go
@@ -91,14 +91,14 @@ func (db *MemDB) StoreExternal(ctx context.Context, duty core.Duty, signedSet co
 		if err != nil {
 			return err
 		} else if !ok {
-			log.Debug(ctx, "Not storing duplicate partial signed data",
-				z.Any("pubkey", pubkey), z.Int("share_idx", sig.ShareIdx))
+			log.Debug(ctx, "Partial signed data ignored since duplicate")
 
 			continue
 		}
 
-		log.Debug(ctx, "Stored partial signed data",
-			z.Any("pubkey", pubkey), z.Int("count", len(sigs)), z.Int("share_idx", sig.ShareIdx))
+		log.Debug(ctx, "Partial signed data stored",
+			z.Int("count", len(sigs)),
+			z.Any("pubkey", pubkey))
 
 		// Call the threshSubs (which includes SigAgg component) if sufficient signatures have been received.
 		if len(sigs) != db.threshold {

diff --git a/core/scheduler/scheduler.go b/core/scheduler/scheduler.go
@@ -18,6 +18,7 @@ package scheduler
 import (
 	"context"
 	"math"
+	"sort"
 	"sync"
 	"testing"
 	"time"
@@ -280,6 +281,11 @@ func (s *Scheduler) resolveAttDuties(ctx context.Context, slot core.Slot, vals v
 		remaining[index] = true
 	}
 
+	// Sort so logging below in ascending slot order.
+	sort.Slice(attDuties, func(i, j int) bool {
+		return attDuties[i].Slot < attDuties[j].Slot
+	})
+
 	for _, attDuty := range attDuties {
 		delete(remaining, attDuty.ValidatorIndex)
 
@@ -301,11 +307,11 @@ func (s *Scheduler) resolveAttDuties(ctx context.Context, slot core.Slot, vals v
 		}
 
 		log.Info(ctx, "Resolved attester duty",
-			z.U64("epoch", uint64(slot.Epoch())),
-			z.U64("vidx", uint64(attDuty.ValidatorIndex)),
 			z.U64("slot", uint64(attDuty.Slot)),
-			z.U64("commidx", uint64(attDuty.CommitteeIndex)),
-			z.Any("pubkey", pubkey))
+			z.U64("vidx", uint64(attDuty.ValidatorIndex)),
+			z.Any("pubkey", pubkey),
+			z.U64("epoch", uint64(slot.Epoch())),
+		)
 
 		// Schedule aggregation duty as well.
 		aggDuty := core.NewAggregatorDuty(int64(attDuty.Slot))

diff --git a/core/sigagg/sigagg.go b/core/sigagg/sigagg.go
@@ -85,7 +85,7 @@ func (a *Aggregator) Aggregate(ctx context.Context, duty core.Duty, pubkey core.
 		return err
 	}
 
-	log.Debug(ctx, "Aggregated threshold partial signatures")
+	log.Debug(ctx, "Threshold aggregated partial signatures")
 
 	// Call subscriptions.
 	for _, sub := range a.subs {

diff --git a/core/validatorapi/validatorapi.go b/core/validatorapi/validatorapi.go
@@ -263,8 +263,6 @@ func (c Component) SubmitAttestations(ctx context.Context, attestations []*eth2p
 		duty := core.NewAttesterDuty(slot)
 		ctx := log.WithCtx(ctx, z.Any("duty", duty))
 
-		log.Debug(ctx, "Attestation(s) submitted by validator client")
-
 		for _, sub := range c.subs {
 			// No need to clone since sub auto clones.
 			err := sub(ctx, duty, set)
@@ -362,6 +360,7 @@ func (c Component) SubmitBeaconBlock(ctx context.Context, block *spec.VersionedS
 	}
 
 	log.Debug(ctx, "Beacon block submitted by validator client")
+
 	signedData, err := core.NewPartialVersionedSignedBeaconBlock(block, c.shareIdx)
 	if err != nil {
 		return err
@@ -516,8 +515,6 @@ func (c Component) submitRegistration(ctx context.Context, registration *eth2api
 		return err
 	}
 
-	log.Debug(ctx, "Builder registration submitted by validator client")
-
 	signedData, err := core.NewPartialVersionedSignedValidatorRegistration(registration, c.shareIdx)
 	if err != nil {
 		return err