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
This commit is contained in:
Peter Rabbitson 2021-05-21 15:00:21 +02:00 committed by Aayush Rajasekaran
parent c1529714e6
commit 3acd846dcd
2 changed files with 45 additions and 31 deletions

View File

@ -658,15 +658,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
}

View File

@ -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) {