logging: reduce log verbosity for hare and others (#3428)

## Motivation
<!-- Please mention the issue fixed by this PR or detailed motivation -->
part of #3134
<!-- `Closes #XXXX, closes #XXXX, ...` links mentioned issues to this PR and automatically closes them when this it's merged -->

## Changes
<!-- Please describe in detail the changes made -->
using systests TestAddNodes as measurement of the log file for a node.

- before 4.3M
- with hare reduced 1.6M (1st commit) (-62.79%)
- with the rest of the change 1.2M (-9.3%)

common/types/ballot.go

@@ -227,9 +227,9 @@ func (b *Ballot) MarshalLogObject(encoder log.ObjectEncoder) error {
 	encoder.AddUint32("epoch_id", uint32(b.LayerIndex.GetEpoch()))
 	encoder.AddString("smesher", b.SmesherID().String())
 	encoder.AddString("base_ballot", b.Votes.Base.String())
-	encoder.AddInt("supports", len(b.Votes.Support))
-	encoder.AddInt("againsts", len(b.Votes.Against))
-	encoder.AddInt("abstains", len(b.Votes.Abstain))
+	encoder.AddInt("support", len(b.Votes.Support))
+	encoder.AddInt("against", len(b.Votes.Against))
+	encoder.AddInt("abstain", len(b.Votes.Abstain))
 	encoder.AddString("atx_id", b.AtxID.String())
 	encoder.AddArray("eligibilities", log.ArrayMarshalerFunc(func(encoder log.ArrayEncoder) error {
 		for _, proof := range b.EligibilityProofs {

hare/algorithm.go

@@ -261,11 +261,7 @@ func (proc *consensusProcess) SetInbox(inbox chan *Msg) {
 func (proc *consensusProcess) eventLoop(ctx context.Context) {
 	logger := proc.WithContext(ctx)
 	logger.With().Info("consensus process started",
-		log.Int("hare_n", proc.cfg.N),
-		log.Int("f", proc.cfg.F),
-		log.Duration("duration", time.Duration(proc.cfg.RoundDuration)*time.Second),
 		proc.instanceID,
-		log.Int("exp_leaders", proc.cfg.ExpectedLeaders),
 		log.String("current_set", proc.s.String()),
 		log.Int("set_size", proc.s.Size()))
 
@@ -282,7 +278,7 @@ func (proc *consensusProcess) eventLoop(ctx context.Context) {
 			m := builder.SetType(pre).Sign(proc.signing).Build()
 			proc.sendMessage(ctx, m)
 		} else {
-			logger.With().Info("should not participate",
+			logger.With().Debug("should not participate",
 				log.Uint32("current_k", proc.getK()),
 				proc.instanceID)
 		}
@@ -309,14 +305,11 @@ PreRound:
 		proc.instanceID,
 		log.Int("set_size", proc.s.Size()))
 	proc.preRoundTracker.FilterSet(proc.s)
-	logger.With().Debug("preround set size after filtering",
-		proc.instanceID,
-		log.Int("set_size", proc.s.Size()))
 	if proc.s.Size() == 0 {
 		logger.Event().Warning("preround ended with empty set",
 			proc.instanceID)
 	} else {
-		logger.With().Info("preround ended",
+		logger.With().Debug("preround ended",
 			log.Int("set_size", proc.s.Size()),
 			proc.instanceID)
 	}
@@ -499,7 +492,7 @@ func (proc *consensusProcess) sendMessage(ctx context.Context, msg *Msg) bool {
 		return false
 	}
 
-	logger.Info("should participate: message sent")
+	logger.Debug("should participate: message sent")
 	return true
 }
 
@@ -520,12 +513,12 @@ func (proc *consensusProcess) onRoundEnd(ctx context.Context) {
 		if s != nil {
 			sStr = s.String()
 		}
-		logger.Event().Info("proposal round ended",
+		logger.Event().Debug("proposal round ended",
 			log.Int("set_size", proc.s.Size()),
 			log.String("proposed_set", sStr),
 			log.Bool("is_conflicting", proc.proposalTracker.IsConflicting()))
 	case commitRound:
-		logger.With().Info("commit round ended", log.Int("set_size", proc.s.Size()))
+		logger.With().Debug("commit round ended", log.Int("set_size", proc.s.Size()))
 	}
 }
 
@@ -615,7 +608,7 @@ func (proc *consensusProcess) beginNotifyRound(ctx context.Context) {
 
 	// send notify message only once
 	if proc.notifySent {
-		logger.Info("begin notify round: notify already sent")
+		logger.Debug("begin notify round: notify already sent")
 		return
 	}
 
@@ -781,7 +774,7 @@ func (proc *consensusProcess) processNotifyMsg(ctx context.Context, msg *Msg) {
 		log.String("current_set", proc.s.String()),
 		log.Uint32("current_k", proc.getK()),
 		proc.instanceID,
-		log.Int("set_size", proc.s.Size()), log.Uint32("K", proc.getK()))
+		log.Int("set_size", proc.s.Size()))
 	proc.report(completed)
 	numIterations.Observe(float64(proc.getK()))
 	proc.terminating = true
@@ -825,7 +818,7 @@ func (proc *consensusProcess) endOfStatusRound() {
 	// assumption: AnalyzeStatuses calls vtFunc for every recorded status message
 	before := time.Now()
 	proc.statusesTracker.AnalyzeStatuses(vtFunc)
-	proc.Event().Info("status round ended",
+	proc.Event().Debug("status round ended",
 		log.Bool("is_svp_ready", proc.statusesTracker.IsSVPReady()),
 		proc.instanceID,
 		log.Int("set_size", proc.s.Size()),
@@ -848,13 +841,13 @@ func (proc *consensusProcess) shouldParticipate(ctx context.Context) bool {
 	}
 
 	if !res {
-		logger.Info("should not participate: identity is not active")
+		logger.Debug("should not participate: identity is not active")
 		return false
 	}
 
 	currentRole := proc.currentRole(ctx)
 	if currentRole == passive {
-		logger.Info("should not participate: passive")
+		logger.Debug("should not participate: passive")
 		return false
 	}
 
@@ -863,7 +856,7 @@ func (proc *consensusProcess) shouldParticipate(ctx context.Context) bool {
 	proc.mu.RUnlock()
 
 	// should participate
-	logger.With().Info("should participate",
+	logger.With().Debug("should participate",
 		log.Bool("leader", currentRole == leader),
 		log.Uint32("eligibility_count", uint32(eligibilityCount)),
 	)

hare/algorithm_test.go

@@ -26,7 +26,6 @@ import (
 var cfg = config.Config{N: 10, F: 5, RoundDuration: 2, ExpectedLeaders: 5, LimitIterations: 1000, LimitConcurrent: 1000}
 
 func newRoundClockFromCfg(logger log.Log, cfg config.Config) *SimpleRoundClock {
-	logger.Info("creating clock at %v wakeup: %v round duration: %v", time.Now(), cfg.WakeupDelta, cfg.RoundDuration)
 	return NewSimpleRoundClock(time.Now(),
 		time.Duration(cfg.WakeupDelta)*time.Second,
 		time.Duration(cfg.RoundDuration)*time.Second,

hare/broker.go

@@ -362,7 +362,7 @@ func (b *Broker) updateSynchronicity(ctx context.Context, id types.LayerID) {
 	// not exist means unknown, check & set
 
 	if !b.nodeSyncState.IsSynced(ctx) {
-		b.WithContext(ctx).With().Info("node is not synced, marking layer as not synced", types.LayerID(id))
+		b.WithContext(ctx).With().Debug("node is not synced, marking layer as not synced", types.LayerID(id))
 		b.syncState[id.Uint32()] = false // mark not synced
 		return
 	}
@@ -409,7 +409,7 @@ func (b *Broker) Register(ctx context.Context, id types.LayerID) (chan *Msg, err
 				instance := b.minDeleted.Add(1)
 				b.mu.RUnlock()
 				b.cleanState(instance)
-				b.With().Info("unregistered layer due to maximum concurrent processes", types.LayerID(instance))
+				b.With().Info("unregistered layer due to maximum concurrent processes", instance)
 			}
 
 			outboxCh := make(chan *Msg, inboxCapacity)
@@ -468,7 +468,7 @@ func (b *Broker) Unregister(ctx context.Context, id types.LayerID) {
 	wg.Add(1)
 	f := func() {
 		b.cleanState(id)
-		b.WithContext(ctx).With().Info("hare broker unregistered layer", id)
+		b.WithContext(ctx).With().Debug("hare broker unregistered layer", id)
 		wg.Done()
 	}
 	select {

hare/eligibility/oracle.go

@@ -363,7 +363,7 @@ func (o *Oracle) CalcEligibility(ctx context.Context, layer types.LayerID, round
 		}
 	}()
 
-	o.With().Info("params",
+	o.With().Debug("params",
 		layer, layer.GetEpoch(), log.Uint32("round_id", round),
 		log.Int("committee_size", committeeSize),
 		log.Int("n", n),
@@ -454,8 +454,7 @@ func (o *Oracle) actives(ctx context.Context, targetLayer types.LayerID) (map[ty
 				logger.With().Error("actives failed to get beacon", epoch, log.Err(err))
 				return nil, fmt.Errorf("error getting beacon for epoch %v: %w", epoch, err)
 			}
-			logger.With().Info("found beacon for epoch", epoch,
-				log.String("epoch_beacon", beacon.ShortString()))
+			logger.With().Debug("found beacon for epoch", epoch, beacon)
 			beacons[epoch] = beacon
 		}
 		blts, err := ballots.Layer(o.cdb, layerID)
@@ -530,7 +529,7 @@ func (o *Oracle) actives(ctx context.Context, targetLayer types.LayerID) (map[ty
 	// if we failed to get a Hare active set, we fall back on reading the Tortoise active set targeting this epoch
 	// TODO: do we want to cache tortoise active set too?
 	if safeLayerStart.GetEpoch().IsGenesis() {
-		logger.With().Info("no hare active set for genesis layer range, reading tortoise set for epoch instead",
+		logger.With().Debug("no hare active set for genesis layer range, reading tortoise set for epoch instead",
 			targetLayer.GetEpoch())
 	} else {
 		logger.With().Warning("no hare active set for layer range, reading tortoise set for epoch instead",
@@ -540,7 +539,6 @@ func (o *Oracle) actives(ctx context.Context, targetLayer types.LayerID) (map[ty
 	if err != nil {
 		return nil, fmt.Errorf("can't get atxs for an epoch %d: %w", targetLayer.GetEpoch()-1, err)
 	}
-	logger.With().Debug("got tortoise atxs", log.Int("count", len(atxids)))
 	if len(atxids) == 0 {
 		return nil, fmt.Errorf("%w: layer %v / epoch %v", errEmptyActiveSet, targetLayer, targetLayer.GetEpoch())
 	}

hare/flows_test.go

@@ -17,7 +17,6 @@ import (
 	"github.com/spacemeshos/go-spacemesh/eligibility"
 	"github.com/spacemeshos/go-spacemesh/hare/config"
 	"github.com/spacemeshos/go-spacemesh/hare/mocks"
-	"github.com/spacemeshos/go-spacemesh/log"
 	"github.com/spacemeshos/go-spacemesh/log/logtest"
 	"github.com/spacemeshos/go-spacemesh/p2p"
 	"github.com/spacemeshos/go-spacemesh/p2p/pubsub"
@@ -263,7 +262,6 @@ func (m *mockClock) advanceLayer() {
 	m.m.Lock()
 	defer m.m.Unlock()
 
-	log.Info("sending for layer %v", m.currentLayer)
 	m.layerTime[m.currentLayer] = time.Now()
 	if ch, ok := m.channels[m.currentLayer]; ok {
 		close(ch)

hare/hare.go

@@ -127,7 +127,7 @@ func New(
 		layerTime := layerClock.LayerToTime(layerID)
 		wakeupDelta := time.Duration(conf.WakeupDelta) * time.Second
 		roundDuration := time.Duration(h.config.RoundDuration) * time.Second
-		h.With().Info("creating hare round clock", layerID,
+		h.With().Debug("creating hare round clock", layerID,
 			log.String("layer_time", layerTime.String()),
 			log.Duration("wakeup_delta", wakeupDelta),
 			log.Duration("round_duration", roundDuration))
@@ -239,7 +239,7 @@ func (h *Hare) collectOutput(ctx context.Context, output TerminationOutput) erro
 		}
 	} else {
 		consensusFailCnt.Inc()
-		h.WithContext(ctx).With().Info("hare terminated with failure", layerID)
+		h.WithContext(ctx).With().Warning("hare terminated with failure", layerID)
 	}
 
 	hareOutput := types.EmptyBlockID
@@ -300,14 +300,14 @@ func (h *Hare) onTick(ctx context.Context, id types.LayerID) (bool, error) {
 	h.setLastLayer(id)
 
 	if id.GetEpoch().IsGenesis() {
-		logger.Info("not starting hare since we are in genesis epoch")
+		logger.Info("not starting hare: genesis")
 		return false, nil
 	}
 
 	var err error
 	beacon, err := h.beacons.GetBeacon(id.GetEpoch())
 	if err != nil {
-		logger.Info("not starting hare since beacon is not retrieved")
+		logger.Info("not starting hare: beacon not retrieved")
 		return false, nil
 	}
 
@@ -340,14 +340,14 @@ func (h *Hare) onTick(ctx context.Context, id types.LayerID) (bool, error) {
 
 	if !h.broker.Synced(ctx, id) {
 		// if not currently synced don't start consensus process
-		logger.Info("not processing hare tick since node is not synced")
+		logger.Info("not starting hare: node not synced at this layer")
 		return false, nil
 	}
 
 	h.layerLock.RLock()
 	proposals := h.getGoodProposal(h.lastLayer, beacon, logger)
 	h.layerLock.RUnlock()
-	logger.With().Info("starting hare consensus with proposals", log.Int("num_proposals", len(proposals)))
+	logger.With().Info("starting hare", log.Int("num_proposals", len(proposals)))
 	preNumProposals.Add(float64(len(proposals)))
 	set := NewSet(proposals)
 
@@ -365,7 +365,7 @@ func (h *Hare) onTick(ctx context.Context, id types.LayerID) (bool, error) {
 		return false, fmt.Errorf("start consensus: %w", err)
 	}
 	h.patrol.SetHareInCharge(instID)
-	logger.With().Info("number of consensus processes (after register)",
+	logger.With().Debug("number of consensus processes (after register)",
 		log.Int32("count", atomic.AddInt32(&h.totalCPs, 1)))
 	return true, nil
 }
@@ -450,7 +450,7 @@ func (h *Hare) outputCollectionLoop(ctx context.Context) {
 			logger := h.WithContext(ctx).WithFields(layerID)
 
 			// collect coinflip, regardless of success
-			logger.With().Info("recording weak coin result for layer",
+			logger.With().Debug("recording weak coin result for layer",
 				log.Bool("weak_coin", coin))
 			if err := layers.SetWeakCoin(h.db, layerID, coin); err != nil {
 				logger.With().Error("failed to set weak coin for layer", log.Err(err))
@@ -459,7 +459,7 @@ func (h *Hare) outputCollectionLoop(ctx context.Context) {
 				logger.With().Warning("error collecting output from hare", log.Err(err))
 			}
 			h.broker.Unregister(ctx, out.ID())
-			logger.With().Info("number of consensus processes (after unregister)",
+			logger.With().Debug("number of consensus processes (after unregister)",
 				log.Int32("count", atomic.AddInt32(&h.totalCPs, -1)))
 		case <-h.CloseChannel():
 			return

hare/preroundtracker.go

@@ -52,7 +52,7 @@ func (pre *preRoundTracker) OnPreRound(ctx context.Context, msg *Msg) {
 		pre.bestVRF = shaUint32
 		// store lowest-order bit as coin toss value
 		pre.coinflip = sha[0]&byte(1) == byte(1)
-		pre.logger.With().Info("got new best vrf value",
+		pre.logger.With().Debug("got new best vrf value",
 			log.String("sender_id", pub.ShortString()),
 			log.String("vrf_value", fmt.Sprintf("%x", shaUint32)),
 			log.Bool("weak_coin", pre.coinflip))
@@ -82,7 +82,7 @@ func (pre *preRoundTracker) OnPreRound(ctx context.Context, msg *Msg) {
 func (pre *preRoundTracker) CanProveValue(value types.ProposalID) bool {
 	// at least threshold occurrences of a given value
 	countStatus := pre.tracker.CountStatus(value)
-	pre.logger.With().Debug("preround tracker count for blockid",
+	pre.logger.With().Debug("preround tracker count",
 		value,
 		log.Uint32("count", countStatus),
 		log.Uint32("threshold", pre.threshold))

hare/proposaltracker.go

@@ -43,7 +43,7 @@ func (pt *proposalTracker) OnProposal(ctx context.Context, msg *Msg) {
 		s := NewSet(msg.InnerMsg.Values)
 		g := NewSet(pt.proposal.InnerMsg.Values)
 		if !s.Equals(g) { // equivocation detected
-			pt.WithContext(ctx).With().Info("equivocation detected on proposal round",
+			pt.WithContext(ctx).With().Warning("equivocation detected on proposal round",
 				log.String("id_malicious", msg.PubKey.String()),
 				log.String("current_set", g.String()),
 				log.String("conflicting_set", s.String()))
@@ -74,7 +74,7 @@ func (pt *proposalTracker) OnLateProposal(ctx context.Context, msg *Msg) {
 		s := NewSet(msg.InnerMsg.Values)
 		g := NewSet(pt.proposal.InnerMsg.Values)
 		if !s.Equals(g) { // equivocation detected
-			pt.WithContext(ctx).With().Info("equivocation detected for late round",
+			pt.WithContext(ctx).With().Warning("equivocation detected for late round",
 				log.String("id_malicious", msg.PubKey.String()),
 				log.String("current_set", g.String()),
 				log.String("conflicting_set", s.String()))
@@ -85,7 +85,7 @@ func (pt *proposalTracker) OnLateProposal(ctx context.Context, msg *Msg) {
 	// not equal check rank
 	// lower ranked proposal on late proposal is a conflict
 	if bytes.Compare(msg.InnerMsg.RoleProof, pt.proposal.InnerMsg.RoleProof) < 0 {
-		pt.With().Info("late lower rank detected",
+		pt.With().Warning("late lower rank detected",
 			log.String("id_malicious", msg.PubKey.String()))
 		pt.isConflicting = true
 	}

miner/proposal_builder.go

@@ -258,16 +258,16 @@ func (pb *ProposalBuilder) handleLayer(ctx context.Context, layerID types.LayerI
 		logger = pb.logger.WithContext(ctx).WithFields(layerID, epoch)
 	)
 
-	logger.Info("builder got layer")
 	if layerID.GetEpoch().IsGenesis() {
+		logger.Info("not building proposal: genesis")
 		return errGenesis
 	}
 	if !pb.syncer.IsSynced(ctx) {
-		logger.Info("not synced yet, not building a proposal")
+		logger.Info("not building proposal: not synced")
 		return errNotSynced
 	}
 	if beacon, err = pb.beaconProvider.GetBeacon(epoch); err != nil {
-		logger.With().Info("beacon not available for epoch", log.Err(err))
+		logger.With().Warning("beacon not available for epoch", log.Err(err))
 		return errNoBeacon
 	}
 
@@ -278,24 +278,23 @@ func (pb *ProposalBuilder) handleLayer(ctx context.Context, layerID types.LayerI
 	atxID, activeSet, proofs, err := pb.proposalOracle.GetProposalEligibility(layerID, beacon)
 	if err != nil {
 		if errors.Is(err, errMinerHasNoATXInPreviousEpoch) {
-			logger.Info("miner has no ATX in previous epoch. not eligible for proposals")
+			logger.Info("miner has no ATX in previous epoch")
 			return fmt.Errorf("miner no ATX: %w", err)
 		}
 		logger.With().Error("failed to check for proposal eligibility", log.Err(err))
 		return fmt.Errorf("proposal eligibility: %w", err)
 	}
 	if len(proofs) == 0 {
-		logger.Info("not eligible for proposal in layer")
+		logger.Debug("not eligible for proposal in layer")
 		return nil
 	}
+	logger.With().Info("eligible for proposals in layer", atxID, log.Int("num_proposals", len(proofs)))
 
 	votes, err := pb.baseBallotProvider.EncodeVotes(ctx, tortoise.EncodeVotesWithCurrent(layerID))
 	if err != nil {
 		return fmt.Errorf("get base ballot: %w", err)
 	}
 
-	logger.With().Info("eligible for one or more proposals in layer", atxID, log.Int("num_proposals", len(proofs)))
-
 	txList := pb.conState.SelectProposalTXs(layerID, len(proofs))
 	p, err := pb.createProposal(ctx, layerID, proofs, atxID, activeSet, beacon, txList, *votes)
 	if err != nil {