From 46a374e6d8c236be7e2df17d9f9d72827bd94d89 Mon Sep 17 00:00:00 2001 From: Edgar Aroutiounian Date: Tue, 3 Mar 2020 12:24:22 -0800 Subject: [PATCH] [project] Never hold reference to global logger (#2365) --- internal/chain/engine.go | 31 ++++++++++++++++----------- shard/committee/assignment.go | 30 +++++++++++++++++--------- staking/availability/measure.go | 37 ++++++++++++++++++++------------- staking/slash/double-sign.go | 28 ++++++++++++++++++------- 4 files changed, 82 insertions(+), 44 deletions(-) diff --git a/internal/chain/engine.go b/internal/chain/engine.go index d85ff3617..9135333b3 100644 --- a/internal/chain/engine.go +++ b/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()))) diff --git a/shard/committee/assignment.go b/shard/committee/assignment.go index 981d12e91..06d4835d9 100644 --- a/shard/committee/assignment.go +++ b/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) diff --git a/staking/availability/measure.go b/staking/availability/measure.go index 895f6970e..e9d85a0f1 100644 --- a/staking/availability/measure.go +++ b/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 diff --git a/staking/slash/double-sign.go b/staking/slash/double-sign.go index e056bc6e2..ea176b2b1 100644 --- a/staking/slash/double-sign.go +++ b/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)