From 308d1e9b7c081a4673a26c00ee9694a0faa301c2 Mon Sep 17 00:00:00 2001 From: Peter Rabbitson Date: Fri, 21 May 2021 15:00:21 +0200 Subject: [PATCH 1/5] Fix logging around mineOne - A nil MiningBaseInfo is *NOT* unexpected: it happens when one is in penalty https://github.com/filecoin-project/lotus/blob/v1.9.0/chain/stmgr/utils.go#L500-L502 - Remove the log from IsRoundWinner(): all we care about is the randbase epoch --- chain/gen/gen.go | 9 ------- miner/miner.go | 67 ++++++++++++++++++++++++++++++++---------------- 2 files changed, 45 insertions(+), 31 deletions(-) diff --git a/chain/gen/gen.go b/chain/gen/gen.go index b4e04424c11..fabe72e49e7 100644 --- a/chain/gen/gen.go +++ b/chain/gen/gen.go @@ -634,15 +634,6 @@ func IsRoundWinner(ctx context.Context, ts *types.TipSet, round abi.ChainEpoch, ep := &types.ElectionProof{VRFProof: vrfout} j := ep.ComputeWinCount(mbi.MinerPower, mbi.NetworkPower) ep.WinCount = j - - log.Infow("completed winAttemptVRF", - "beaconRound", brand.Round, - "beaconDataB64", b64.EncodeToString(brand.Data), - "electionRandB64", b64.EncodeToString(electionRand), - "vrfB64", b64.EncodeToString(vrfout), - "winCount", j, - ) - if j < 1 { return nil, nil } diff --git a/miner/miner.go b/miner/miner.go index a77e1c18bc5..5fbc9aae30c 100644 --- a/miner/miner.go +++ b/miner/miner.go @@ -18,6 +18,7 @@ import ( "github.com/filecoin-project/go-address" "github.com/filecoin-project/go-state-types/abi" + "github.com/filecoin-project/go-state-types/big" "github.com/filecoin-project/go-state-types/crypto" lru "github.com/hashicorp/golang-lru" @@ -415,36 +416,51 @@ func (m *Miner) GetBestMiningCandidate(ctx context.Context) (*MiningBase, error) // This method does the following: // // 1. -func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, error) { +func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *types.BlockMsg, err error) { log.Debugw("attempting to mine a block", "tipset", types.LogCids(base.TipSet.Cids())) start := build.Clock.Now() round := base.TipSet.Height() + base.NullRounds + 1 - mbi, err := m.api.MinerGetBaseInfo(ctx, m.address, round, base.TipSet.Key()) - if err != nil { - return nil, xerrors.Errorf("failed to get mining base info: %w", err) - } - if mbi == nil { - log.Warnf("mineOne: unexpectedly nil MiningBaseInfo for round %d, off tipset %d/%s", round, base.TipSet.Height(), base.TipSet.Key().String()) - return nil, nil - } - - // always write out a log from this point out + // always write out a log var winner *types.ElectionProof + var mbi *api.MiningBaseInfo + var rbase types.BeaconEntry defer func() { + // mbi can be nil if we are deep in penalty and there are 0 eligible sectors + // in the current deadline. If this case - put together a dummy one for reporting + // https://github.com/filecoin-project/lotus/blob/v1.9.0/chain/stmgr/utils.go#L500-L502 + if mbi == nil { + mbi = &api.MiningBaseInfo{ + NetworkPower: big.NewInt(-1), // we do not know how big the network is at this point + EligibleForMining: false, + MinerPower: big.NewInt(0), // but we do know we do not have anything + } + } + log.Infow( "completed mineOne", "forRound", int64(round), "baseEpoch", int64(base.TipSet.Height()), + "beaconEpoch", rbase.Round, "lookbackEpochs", int64(policy.ChainFinality), // hardcoded as it is unlikely to change again: https://github.com/filecoin-project/lotus/blob/v1.8.0/chain/actors/policy/policy.go#L180-L186 "networkPowerAtLookback", mbi.NetworkPower.String(), "minerPowerAtLookback", mbi.MinerPower.String(), "isEligible", mbi.EligibleForMining, "isWinner", (winner != nil), + "error", err, ) }() + mbi, err = m.api.MinerGetBaseInfo(ctx, m.address, round, base.TipSet.Key()) + if err != nil { + err = xerrors.Errorf("failed to get mining base info: %w", err) + return nil, err + } + if mbi == nil { + return nil, nil + } + if !mbi.EligibleForMining { // slashed or just have no power yet return nil, nil @@ -461,19 +477,21 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, log.Infof("Time delta between now and our mining base: %ds (nulls: %d)", uint64(build.Clock.Now().Unix())-base.TipSet.MinTimestamp(), base.NullRounds) - rbase := beaconPrev + rbase = beaconPrev if len(bvals) > 0 { rbase = bvals[len(bvals)-1] } ticket, err := m.computeTicket(ctx, &rbase, base, mbi) if err != nil { - return nil, xerrors.Errorf("scratching ticket failed: %w", err) + err = xerrors.Errorf("scratching ticket failed: %w", err) + return nil, err } winner, err = gen.IsRoundWinner(ctx, base.TipSet, round, m.address, rbase, mbi, m.api) if err != nil { - return nil, xerrors.Errorf("failed to check if we win next round: %w", err) + err = xerrors.Errorf("failed to check if we win next round: %w", err) + return nil, err } if winner == nil { @@ -484,12 +502,14 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, buf := new(bytes.Buffer) if err := m.address.MarshalCBOR(buf); err != nil { - return nil, xerrors.Errorf("failed to marshal miner address: %w", err) + err = xerrors.Errorf("failed to marshal miner address: %w", err) + return nil, err } rand, err := store.DrawRandomness(rbase.Data, crypto.DomainSeparationTag_WinningPoStChallengeSeed, round, buf.Bytes()) if err != nil { - return nil, xerrors.Errorf("failed to get randomness for winning post: %w", err) + err = xerrors.Errorf("failed to get randomness for winning post: %w", err) + return nil, err } prand := abi.PoStRandomness(rand) @@ -498,7 +518,8 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, postProof, err := m.epp.ComputeProof(ctx, mbi.Sectors, prand) if err != nil { - return nil, xerrors.Errorf("failed to compute winning post proof: %w", err) + err = xerrors.Errorf("failed to compute winning post proof: %w", err) + return nil, err } tProof := build.Clock.Now() @@ -506,15 +527,17 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, // get pending messages early, msgs, err := m.api.MpoolSelect(context.TODO(), base.TipSet.Key(), ticket.Quality()) if err != nil { - return nil, xerrors.Errorf("failed to select messages for block: %w", err) + err = xerrors.Errorf("failed to select messages for block: %w", err) + return nil, err } tPending := build.Clock.Now() // TODO: winning post proof - b, err := m.createBlock(base, m.address, ticket, winner, bvals, postProof, msgs) + minedBlock, err = m.createBlock(base, m.address, ticket, winner, bvals, postProof, msgs) if err != nil { - return nil, xerrors.Errorf("failed to create block: %w", err) + err = xerrors.Errorf("failed to create block: %w", err) + return nil, err } tCreateBlock := build.Clock.Now() @@ -523,7 +546,7 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, for i, header := range base.TipSet.Blocks() { parentMiners[i] = header.Miner } - log.Infow("mined new block", "cid", b.Cid(), "height", int64(b.Header.Height), "miner", b.Header.Miner, "parents", parentMiners, "parentTipset", base.TipSet.Key().String(), "took", dur) + log.Infow("mined new block", "cid", minedBlock.Cid(), "height", int64(minedBlock.Header.Height), "miner", minedBlock.Header.Miner, "parents", parentMiners, "parentTipset", base.TipSet.Key().String(), "took", dur) if dur > time.Second*time.Duration(build.BlockDelaySecs) { log.Warnw("CAUTION: block production took longer than the block delay. Your computer may not be fast enough to keep up", "tMinerBaseInfo ", tMBI.Sub(start), @@ -536,7 +559,7 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, "tCreateBlock ", tCreateBlock.Sub(tPending)) } - return b, nil + return minedBlock, nil } func (m *Miner) computeTicket(ctx context.Context, brand *types.BeaconEntry, base *MiningBase, mbi *api.MiningBaseInfo) (*types.Ticket, error) { From aed7017ab2aeeb8f8aa7f9e980ad21cf0d608063 Mon Sep 17 00:00:00 2001 From: Peter Rabbitson Date: Fri, 21 May 2021 15:30:08 +0200 Subject: [PATCH 2/5] Forgotten deadcode --- chain/gen/gen.go | 3 --- 1 file changed, 3 deletions(-) diff --git a/chain/gen/gen.go b/chain/gen/gen.go index fabe72e49e7..d06c755fa34 100644 --- a/chain/gen/gen.go +++ b/chain/gen/gen.go @@ -3,7 +3,6 @@ package gen import ( "bytes" "context" - "encoding/base64" "fmt" "io" "io/ioutil" @@ -611,8 +610,6 @@ func (wpp *wppProvider) ComputeProof(context.Context, []proof2.SectorInfo, abi.P return ValidWpostForTesting, nil } -var b64 = base64.URLEncoding.WithPadding(base64.NoPadding) - func IsRoundWinner(ctx context.Context, ts *types.TipSet, round abi.ChainEpoch, miner address.Address, brand types.BeaconEntry, mbi *api.MiningBaseInfo, a MiningCheckAPI) (*types.ElectionProof, error) { From 888c63b79c93c186242c59373f7024e793fbfd81 Mon Sep 17 00:00:00 2001 From: Peter Rabbitson Date: Sat, 22 May 2021 17:39:56 +0200 Subject: [PATCH 3/5] Incorporate the 'Time delta between now...' log into the 'completed mineOne' --- miner/miner.go | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/miner/miner.go b/miner/miner.go index 5fbc9aae30c..7b85e558efd 100644 --- a/miner/miner.go +++ b/miner/miner.go @@ -440,9 +440,12 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *type log.Infow( "completed mineOne", + "tookMilliseconds", (build.Clock.Now().UnixNano()-start.UnixNano())/1_000_000, "forRound", int64(round), "baseEpoch", int64(base.TipSet.Height()), - "beaconEpoch", rbase.Round, + "baseDeltaSeconds", uint64(start.Unix())-base.TipSet.MinTimestamp(), + "nullRounds", int64(base.NullRounds), + "beaconEpoch", uint64(rbase.Round), "lookbackEpochs", int64(policy.ChainFinality), // hardcoded as it is unlikely to change again: https://github.com/filecoin-project/lotus/blob/v1.8.0/chain/actors/policy/policy.go#L180-L186 "networkPowerAtLookback", mbi.NetworkPower.String(), "minerPowerAtLookback", mbi.MinerPower.String(), @@ -475,8 +478,6 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *type tPowercheck := build.Clock.Now() - log.Infof("Time delta between now and our mining base: %ds (nulls: %d)", uint64(build.Clock.Now().Unix())-base.TipSet.MinTimestamp(), base.NullRounds) - rbase = beaconPrev if len(bvals) > 0 { rbase = bvals[len(bvals)-1] From 3a74ab8f8249587ae6374191f9c276ff2597a535 Mon Sep 17 00:00:00 2001 From: Peter Rabbitson Date: Sat, 22 May 2021 23:55:32 +0200 Subject: [PATCH 4/5] Add a `lateStart` indicator, differentiate on Error/Warn/Info --- miner/miner.go | 21 ++++++++++++++++----- 1 file changed, 16 insertions(+), 5 deletions(-) diff --git a/miner/miner.go b/miner/miner.go index 7b85e558efd..b2da25d8e48 100644 --- a/miner/miner.go +++ b/miner/miner.go @@ -13,6 +13,7 @@ import ( proof2 "github.com/filecoin-project/specs-actors/v2/actors/runtime/proof" + "github.com/filecoin-project/lotus/chain/actors/builtin" "github.com/filecoin-project/lotus/chain/actors/policy" "github.com/filecoin-project/lotus/chain/gen/slashfilter" @@ -438,13 +439,15 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *type } } - log.Infow( - "completed mineOne", - "tookMilliseconds", (build.Clock.Now().UnixNano()-start.UnixNano())/1_000_000, + isLate := uint64(start.Unix()) > (base.TipSet.MinTimestamp() + uint64(base.NullRounds*builtin.EpochDurationSeconds) + build.PropagationDelaySecs) + + logStruct := []interface{}{ + "tookMilliseconds", (build.Clock.Now().UnixNano() - start.UnixNano()) / 1_000_000, "forRound", int64(round), "baseEpoch", int64(base.TipSet.Height()), - "baseDeltaSeconds", uint64(start.Unix())-base.TipSet.MinTimestamp(), + "baseDeltaSeconds", uint64(start.Unix()) - base.TipSet.MinTimestamp(), "nullRounds", int64(base.NullRounds), + "lateStart", isLate, "beaconEpoch", uint64(rbase.Round), "lookbackEpochs", int64(policy.ChainFinality), // hardcoded as it is unlikely to change again: https://github.com/filecoin-project/lotus/blob/v1.8.0/chain/actors/policy/policy.go#L180-L186 "networkPowerAtLookback", mbi.NetworkPower.String(), @@ -452,7 +455,15 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *type "isEligible", mbi.EligibleForMining, "isWinner", (winner != nil), "error", err, - ) + } + + if err != nil { + log.Errorw("completed mineOne", logStruct...) + } else if isLate { + log.Warnw("completed mineOne", logStruct...) + } else { + log.Infow("completed mineOne", logStruct...) + } }() mbi, err = m.api.MinerGetBaseInfo(ctx, m.address, round, base.TipSet.Key()) From 391d6eca49f4ea0288547ce96fc982a97aaec63a Mon Sep 17 00:00:00 2001 From: Jennifer Wang Date: Mon, 24 May 2021 10:04:37 -0400 Subject: [PATCH 5/5] make lint happy --- miner/miner.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/miner/miner.go b/miner/miner.go index b2da25d8e48..62bec5b55f4 100644 --- a/miner/miner.go +++ b/miner/miner.go @@ -448,7 +448,7 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (minedBlock *type "baseDeltaSeconds", uint64(start.Unix()) - base.TipSet.MinTimestamp(), "nullRounds", int64(base.NullRounds), "lateStart", isLate, - "beaconEpoch", uint64(rbase.Round), + "beaconEpoch", rbase.Round, "lookbackEpochs", int64(policy.ChainFinality), // hardcoded as it is unlikely to change again: https://github.com/filecoin-project/lotus/blob/v1.8.0/chain/actors/policy/policy.go#L180-L186 "networkPowerAtLookback", mbi.NetworkPower.String(), "minerPowerAtLookback", mbi.MinerPower.String(),