core: improve logging (#636)

Improve logging in core workflow. Add proper topics. Remove duplicate beacon mock logs.

category: refactor
ticket: none

core/bcast/bcast.go

@@ -52,6 +52,7 @@ type Broadcaster struct {
 func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty,
 	pubkey core.PubKey, aggData core.AggSignedData,
 ) (err error) {
+	ctx = log.WithTopic(ctx, "bcast")
 	defer func() {
 		if err == nil {
 			instrumentDuty(duty, pubkey)
@@ -67,7 +68,11 @@ func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty,
 
 		err = b.eth2Cl.SubmitAttestations(ctx, []*eth2p0.Attestation{att})
 		if err == nil {
-			log.Info(ctx, "Attestation submitted successfully to beacon node", z.Int("slot", int(duty.Slot)))
+			log.Info(ctx, "Attestation successfully submitted to beacon node",
+				z.U64("slot", uint64(att.Data.Slot)),
+				z.U64("target_epoch", uint64(att.Data.Target.Epoch)),
+				z.Hex("agg_bits", att.AggregationBits.Bytes()),
+			)
 		}
 
 		return err
@@ -79,7 +84,9 @@ func (b Broadcaster) Broadcast(ctx context.Context, duty core.Duty,
 
 		err = b.eth2Cl.SubmitBeaconBlock(ctx, block)
 		if err == nil {
-			log.Info(ctx, "Block submitted successfully to beacon node", z.Int("slot", int(duty.Slot)))
+			log.Info(ctx, "Block proposal successfully submitted to beacon node",
+				z.U64("slot", uint64(duty.Slot)),
+			)
 		}
 
 		return err

core/leadercast/leadercast.go

@@ -92,6 +92,8 @@ func (l *LeaderCast) Subscribe(fn func(ctx context.Context, duty core.Duty, set
 // Propose proposes an unsigned duty data object for consensus. If this peer is the leader, then it is
 // broadcasted to all peers (including self), else the proposal is ignored.
 func (l *LeaderCast) Propose(ctx context.Context, duty core.Duty, data core.UnsignedDataSet) error {
+	ctx = log.WithTopic(ctx, "lcast")
+
 	if !isLeader(l.peerIdx, l.peers, duty) {
 		return nil
 	}

core/leadercast/transport.go

@@ -104,10 +104,10 @@ func (t *p2pTransport) Broadcast(ctx context.Context, fromIdx int, d core.Duty,
 	}
 
 	if len(errs) == 0 {
-		log.Debug(ctx, "Leader broadcast duty success", z.Any("duty", d))
+		log.Debug(ctx, "Leader propose value success", z.Any("duty", d))
 	} else {
 		// len(t.peers)-len(errs)-1 is total number of errors excluding broadcast to self case
-		log.Warn(ctx, "Broadcast duty with errors", errs[0], z.Int("success", len(t.peers)-len(errs)-1),
+		log.Warn(ctx, "Leader propose value with errors", errs[0], z.Int("success", len(t.peers)-len(errs)-1),
 			z.Int("errors", len(errs)))
 	}
 

core/parsigex/parsigex.go

@@ -90,6 +90,8 @@ func (m *ParSigEx) handle(s network.Stream) {
 
 // Broadcast broadcasts the partially signed duty data set to all peers.
 func (m *ParSigEx) Broadcast(ctx context.Context, duty core.Duty, set core.ParSignedDataSet) error {
+	ctx = log.WithTopic(ctx, "parsigex")
+
 	b, err := proto.Marshal(&pbv1.ParSigExMsg{
 		Duty:    core.DutyToProto(duty),
 		DataSet: core.ParSignedDataSetToProto(set),
@@ -98,7 +100,10 @@ func (m *ParSigEx) Broadcast(ctx context.Context, duty core.Duty, set core.ParSi
 		return errors.Wrap(err, "marshal msg proto")
 	}
 
-	var errs []error
+	var (
+		errs    []error
+		success int
+	)
 
 	for i, p := range m.peers {
 		// Don't send to self
@@ -109,14 +114,16 @@ func (m *ParSigEx) Broadcast(ctx context.Context, duty core.Duty, set core.ParSi
 		err := sendData(ctx, m.tcpNode, p, b)
 		if err != nil {
 			errs = append(errs, err)
+		} else {
+			success++
 		}
 	}
 
 	if len(errs) == 0 {
-		log.Debug(ctx, "parsigex broadcast duty success", z.Any("duty", duty))
+		log.Debug(ctx, "Exchange partial signature(s) success", z.Any("duty", duty))
 	} else {
 		// len(t.peers)-len(errs)-1 is total number of errors excluding broadcast to self case
-		log.Warn(ctx, "broadcast duty with errors", errs[0], z.Int("success", len(m.peers)-len(errs)-1),
+		log.Warn(ctx, "Exchange partial signature(s) with errors", errs[0], z.Int("success", success),
 			z.Int("errors", len(errs)))
 	}
 

core/scheduler/scheduler.go

@@ -180,6 +180,7 @@ func (s *Scheduler) scheduleSlot(ctx context.Context, slot slot) {
 			}
 
 			instrumentDuty(duty, argSet)
+			ctx = log.WithCtx(ctx, z.Any("duty", duty))
 			ctx, span := core.StartDutyTrace(ctx, duty, "core/scheduler.scheduleSlot")
 			defer span.End()
 

testutil/beaconmock/options.go

@@ -35,7 +35,6 @@ import (
 
 	"github.com/obolnetwork/charon/app/errors"
 	"github.com/obolnetwork/charon/app/log"
-	"github.com/obolnetwork/charon/app/z"
 	"github.com/obolnetwork/charon/core"
 	"github.com/obolnetwork/charon/testutil"
 )
@@ -399,24 +398,9 @@ func defaultMock(httpMock HTTPMock, httpServer *http.Server, clock clockwork.Clo
 			return nil, nil
 		},
 		SubmitAttestationsFunc: func(ctx context.Context, atts []*eth2p0.Attestation) error {
-			for _, att := range atts {
-				log.Info(ctx, "Attestation submitted to beacon node",
-					z.U64("slot", uint64(att.Data.Slot)),
-					z.U64("target_epoch", uint64(att.Data.Target.Epoch)),
-					z.Hex("agg_bits", att.AggregationBits.Bytes()),
-				)
-			}
-
 			return nil
 		},
 		SubmitBeaconBlockFunc: func(ctx context.Context, block *spec.VersionedSignedBeaconBlock) error {
-			slot, err := block.Slot()
-			if err != nil {
-				return err
-			}
-
-			log.Info(ctx, "Block submitted to beacon node", z.U64("slot", uint64(slot)))
-
 			return nil
 		},
 		GenesisTimeFunc: func(ctx context.Context) (time.Time, error) {