[project] Never hold reference to global logger (#2365)

internal/chain/engine.go

@@ -301,11 +301,6 @@ func (e *engineImpl) Finalize(
 		}
 	}
 
-	l := utils.Logger().Info().
-		Uint64("current-epoch", chain.CurrentHeader().Epoch().Uint64()).
-		Uint64("finalizing-epoch", header.Epoch().Uint64()).
-		Uint64("block-number", header.Number().Uint64())
-
 	if isBeaconChain && inStakingEra {
 		nowEpoch := chain.CurrentHeader().Epoch()
 		superCommittee, err := chain.ReadShardState(nowEpoch)
@@ -315,7 +310,11 @@ func (e *engineImpl) Finalize(
 		staked := superCommittee.StakedValidators()
 		// could happen that only harmony nodes are running,
 		if isNewEpoch && staked.CountStakedValidator > 0 {
-			l.Msg("in new epoch (aka last block), apply availability check for activity")
+			utils.Logger().Info().
+				Uint64("current-epoch", chain.CurrentHeader().Epoch().Uint64()).
+				Uint64("finalizing-epoch", header.Epoch().Uint64()).
+				Uint64("block-number", header.Number().Uint64()).
+				Msg("in new epoch (aka last block), apply availability check for activity")
 			if err := availability.SetInactiveUnavailableValidators(
 				chain, state, staked.Addrs,
 			); err != nil {
@@ -362,10 +361,13 @@ func (e *engineImpl) Finalize(
 		// Apply the slashes, invariant: assume been verified as legit slash by this point
 		var slashApplied *slash.Application
 		rate := slash.Rate(caught, staked.CountStakedBLSKey)
-		lg := l.Str("rate", rate.String()).
-			RawJSON("records", []byte(doubleSigners.String()))
-
-		lg.Msg("now applying slash to state during block finalization")
+		utils.Logger().Info().
+			Uint64("current-epoch", chain.CurrentHeader().Epoch().Uint64()).
+			Uint64("finalizing-epoch", header.Epoch().Uint64()).
+			Uint64("block-number", header.Number().Uint64()).
+			Str("rate", rate.String()).
+			RawJSON("records", []byte(doubleSigners.String())).
+			Msg("now applying slash to state during block finalization")
 		if slashApplied, err = slash.Apply(
 			chain,
 			state,
@@ -375,9 +377,14 @@ func (e *engineImpl) Finalize(
 			return nil, nil, ctxerror.New("[Finalize] could not apply slash").WithCause(err)
 		}
 
-		lg.RawJSON("applied", []byte(slashApplied.String())).
+		utils.Logger().Info().
+			Uint64("current-epoch", chain.CurrentHeader().Epoch().Uint64()).
+			Uint64("finalizing-epoch", header.Epoch().Uint64()).
+			Uint64("block-number", header.Number().Uint64()).
+			Str("rate", rate.String()).
+			RawJSON("records", []byte(doubleSigners.String())).
+			RawJSON("applied", []byte(slashApplied.String())).
 			Msg("slash applied successfully")
-
 	}
 
 	header.SetRoot(state.IntermediateRoot(chain.Config().IsS3(header.Epoch())))

shard/committee/assignment.go

@@ -116,10 +116,12 @@ func eposStakedCommittee(
 ) (*shard.State, error) {
 	// TODO Nervous about this because overtime the list will become quite large
 	candidates := stakerReader.ValidatorCandidates()
-	essentials := map[common.Address]effective.SlotOrder{}
-	l := utils.Logger().Info().Int("staked-candidates", len(candidates))
-	l.Msg("preparing epos staked committee")
-	blsKeys := make(map[shard.BlsPublicKey]struct{})
+	essentials, blsKeys :=
+		map[common.Address]effective.SlotOrder{}, map[shard.BlsPublicKey]struct{}{}
+
+	utils.Logger().Info().
+		Int("staked-candidates", len(candidates)).
+		Msg("preparing epos staked committee")
 
 	// TODO benchmark difference if went with data structure that sorts on insert
 	for i := range candidates {
@@ -128,12 +130,16 @@ func eposStakedCommittee(
 			return nil, err
 		}
 		if !effective.IsEligibleForEPOSAuction(validator) {
-			l.RawJSON("candidate", []byte(validator.String())).
+			utils.Logger().Info().
+				Int("staked-candidates", len(candidates)).
+				RawJSON("candidate", []byte(validator.String())).
 				Msg("validator not eligible for epos")
 			continue
 		}
 		if err := validator.SanityCheck(); err != nil {
-			l.Err(err).
+			utils.Logger().Info().
+				Int("staked-candidates", len(candidates)).
+				Err(err).
 				RawJSON("candidate", []byte(validator.String())).
 				Msg("validator sanity check failed")
 			continue
@@ -155,7 +161,9 @@ func eposStakedCommittee(
 		}
 		if found {
 			const m = "Duplicate bls key found %x, in validator %+v. Ignoring"
-			l.Msgf(m, dupKey, validator)
+			utils.Logger().Info().
+				Int("staked-candidates", len(candidates)).
+				Msgf(m, dupKey, validator)
 			continue
 		}
 
@@ -188,7 +196,9 @@ func eposStakedCommittee(
 	}
 
 	if stakedSlotsCount == 0 {
-		l.Int("slots-for-epos", stakedSlotsCount).
+		utils.Logger().Info().
+			Int("staked-candidates", len(candidates)).
+			Int("slots-for-epos", stakedSlotsCount).
 			Msg("committe composed only of harmony node")
 		return shardState, nil
 	}
@@ -215,7 +225,8 @@ func eposStakedCommittee(
 	}
 
 	if c := len(candidates); c != 0 {
-		l.Int("staked-candidates", c).
+		utils.Logger().Info().
+			Int("staked-candidates", c).
 			Str("total-staked-by-validators", totalStake.String()).
 			RawJSON("staked-super-committee", []byte(shardState.String())).
 			Msg("epos based super-committe")
@@ -227,7 +238,6 @@ func eposStakedCommittee(
 // GetCommitteePublicKeys returns the public keys of a shard
 func (def partialStakingEnabled) GetCommitteePublicKeys(committee *shard.Committee) []*bls.PublicKey {
 	allIdentities := make([]*bls.PublicKey, len(committee.Slots))
-
 	for i := range committee.Slots {
 		identity := &bls.PublicKey{}
 		committee.Slots[i].BlsPublicKey.ToLibBLSPublicKey(identity)

staking/availability/measure.go

@@ -118,7 +118,6 @@ func bumpCount(
 	didSign bool,
 	stakedAddrSet map[common.Address]struct{},
 ) error {
-	l := utils.Logger().Info()
 	for i := range signers {
 		addr := signers[i].EcdsaAddress
 		// NOTE if the signer address is not part of the staked addrs,
@@ -133,7 +132,7 @@ func bumpCount(
 			return err
 		}
 
-		l.RawJSON("validator", []byte(wrapper.String())).
+		utils.Logger().Info().RawJSON("validator", []byte(wrapper.String())).
 			Msg("about to adjust counters")
 
 		wrapper.Counters.NumBlocksToSign.Add(
@@ -146,7 +145,7 @@ func bumpCount(
 			)
 		}
 
-		l.RawJSON("validator", []byte(wrapper.String())).
+		utils.Logger().Info().RawJSON("validator", []byte(wrapper.String())).
 			Msg("bumped signing counters")
 
 		if err := state.UpdateValidatorWrapper(
@@ -165,18 +164,20 @@ func IncrementValidatorSigningCounts(
 	state *state.DB,
 	signers, missing shard.SlotList,
 ) error {
-	l := utils.Logger().Info()
-	l.RawJSON("missing", []byte(missing.String())).
+	utils.Logger().Info().
+		RawJSON("missing", []byte(missing.String())).
 		Msg("signers that did sign")
 
-	l.Msg("bumping signing counters for non-missing signers")
+	utils.Logger().Info().
+		Msg("bumping signing counters for non-missing signers")
 
 	if err := bumpCount(
 		bc, state, signers, true, staked.LookupSet,
 	); err != nil {
 		return err
 	}
-	l.Msg("bumping missing signers counters")
+	utils.Logger().Info().
+		Msg("bumping missing signers counters")
 	return bumpCount(bc, state, missing, false, staked.LookupSet)
 }
 
@@ -210,11 +211,10 @@ func SetInactiveUnavailableValidators(
 			snapshot.Counters.NumBlocksSigned,
 			snapshot.Counters.NumBlocksToSign
 
-		l := utils.Logger().Info().
+		utils.Logger().Info().
 			RawJSON("snapshot", []byte(snapshot.String())).
-			RawJSON("current", []byte(wrapper.String()))
-
-		l.Msg("begin checks for availability")
+			RawJSON("current", []byte(wrapper.String())).
+			Msg("begin checks for availability")
 
 		signed, toSign :=
 			new(big.Int).Sub(statsNow.NumBlocksSigned, snapSigned),
@@ -235,7 +235,10 @@ func SetInactiveUnavailableValidators(
 		}
 
 		if toSign.Cmp(common.Big0) == 0 {
-			l.Msg("toSign is 0, perhaps did not receive crosslink proving signing")
+			utils.Logger().Info().
+				RawJSON("snapshot", []byte(snapshot.String())).
+				RawJSON("current", []byte(wrapper.String())).
+				Msg("toSign is 0, perhaps did not receive crosslink proving signing")
 			continue
 		}
 
@@ -243,7 +246,10 @@ func SetInactiveUnavailableValidators(
 			numeric.NewDecFromBigInt(signed), numeric.NewDecFromBigInt(toSign)
 		quotient := s1.Quo(s2)
 
-		l.Str("signed", s1.String()).
+		utils.Logger().Info().
+			RawJSON("snapshot", []byte(snapshot.String())).
+			RawJSON("current", []byte(wrapper.String())).
+			Str("signed", s1.String()).
 			Str("to-sign", s2.String()).
 			Str("percentage-signed", quotient.String()).
 			Bool("meets-threshold", quotient.LTE(measure)).
@@ -251,7 +257,10 @@ func SetInactiveUnavailableValidators(
 
 		if quotient.LTE(measure) {
 			wrapper.Active = false
-			l.Str("threshold", measure.String()).
+			utils.Logger().Info().
+				RawJSON("snapshot", []byte(snapshot.String())).
+				RawJSON("current", []byte(wrapper.String())).
+				Str("threshold", measure.String()).
 				Msg("validator failed availability threshold, set to inactive")
 			if err := state.UpdateValidatorWrapper(addrs[i], wrapper); err != nil {
 				return err

staking/slash/double-sign.go

@@ -253,10 +253,10 @@ func delegatorSlashApply(
 		snapshotAddr := delegationSnapshot.DelegatorAddress
 		for _, delegationNow := range current.Delegations {
 			if nowAmt := delegationNow.Amount; delegationNow.DelegatorAddress == snapshotAddr {
-				l := utils.Logger().Info().RawJSON("delegation-snapshot", []byte(delegationSnapshot.String())).
-					RawJSON("delegation-current", []byte(delegationNow.String()))
-
-				l.Uint64("initial-slash-debt", slashDebt.Uint64()).
+				utils.Logger().Info().
+					RawJSON("delegation-snapshot", []byte(delegationSnapshot.String())).
+					RawJSON("delegation-current", []byte(delegationNow.String())).
+					Uint64("initial-slash-debt", slashDebt.Uint64()).
 					Str("rate", rate.String()).
 					Msg("attempt to apply slashing based on snapshot amount to current state")
 				// Current delegation has some money and slashdebt is still not paid off
@@ -273,7 +273,10 @@ func delegatorSlashApply(
 					// such that epoch>= doubleSignEpoch should be slashable
 					if undelegate.Epoch.Cmp(doubleSignEpoch) >= 0 {
 						if slashDebt.Cmp(common.Big0) <= 0 {
-							l.Msg("paid off the slash debt")
+							utils.Logger().Info().
+								RawJSON("delegation-snapshot", []byte(delegationSnapshot.String())).
+								RawJSON("delegation-current", []byte(delegationNow.String())).
+								Msg("paid off the slash debt")
 							break
 						}
 						nowAmt := undelegate.Amount
@@ -285,7 +288,10 @@ func delegatorSlashApply(
 
 						if nowAmt.Cmp(common.Big0) == 0 {
 							// TODO need to remove the undelegate
-							l.Msg("delegation amount after paying slash debt is 0")
+							utils.Logger().Info().
+								RawJSON("delegation-snapshot", []byte(delegationSnapshot.String())).
+								RawJSON("delegation-current", []byte(delegationNow.String())).
+								Msg("delegation amount after paying slash debt is 0")
 						}
 					}
 				}
@@ -296,7 +302,10 @@ func delegatorSlashApply(
 				// then we need to take from their pending rewards
 				if slashDebt.Cmp(common.Big0) == 1 {
 					nowAmt := delegationNow.Reward
-					l.Uint64("slash-debt", slashDebt.Uint64()).
+					utils.Logger().Info().
+						RawJSON("delegation-snapshot", []byte(delegationSnapshot.String())).
+						RawJSON("delegation-current", []byte(delegationNow.String())).
+						Uint64("slash-debt", slashDebt.Uint64()).
 						Uint64("now-amount-reward", nowAmt.Uint64()).
 						Msg("needed to dig into reward to pay off slash debt")
 					if err := payDownAsMuchAsCan(
@@ -310,7 +319,10 @@ func delegatorSlashApply(
 				// they only get half of what was actually dispersed
 				halfOfSlashDebt := new(big.Int).Div(slashDiff.TotalSlashed, common.Big2)
 				slashDiff.TotalSnitchReward.Add(slashDiff.TotalSnitchReward, halfOfSlashDebt)
-				l.Uint64("reporter-reward", halfOfSlashDebt.Uint64()).
+				utils.Logger().Info().
+					RawJSON("delegation-snapshot", []byte(delegationSnapshot.String())).
+					RawJSON("delegation-current", []byte(delegationNow.String())).
+					Uint64("reporter-reward", halfOfSlashDebt.Uint64()).
 					RawJSON("application", []byte(slashDiff.String())).
 					Msg("completed an application of slashing")
 				state.AddBalance(reporter, halfOfSlashDebt)