Merge pull request #6196 from filecoin-project/feat/fwdport_more_logs…

…_PR6183

This is a 1:1 forward-port of PR#6183 from 1.9.x to master

chain/actors/policy/policy.go

@@ -187,6 +187,7 @@ func GetWinningPoStSectorSetLookback(nwVer network.Version) abi.ChainEpoch {
 		return 10
 	}
 
+	// NOTE: if this ever changes, adjust it in a (*Miner).mineOne() logline as well
 	return ChainFinality
 }
 

chain/gen/gen.go

@@ -3,6 +3,7 @@ package gen
 import (
 	"bytes"
 	"context"
+	"encoding/base64"
 	"fmt"
 	"io"
 	"io/ioutil"
@@ -610,6 +611,8 @@ 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) {
 
@@ -631,6 +634,15 @@ 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
 	}

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/policy"
 	"github.com/filecoin-project/lotus/chain/gen/slashfilter"
 
 	"github.com/filecoin-project/go-address"
@@ -425,8 +426,25 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg,
 		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
+	var winner *types.ElectionProof
+	defer func() {
+		log.Infow(
+			"completed mineOne",
+			"forRound", int64(round),
+			"baseEpoch", int64(base.TipSet.Height()),
+			"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),
+		)
+	}()
+
 	if !mbi.EligibleForMining {
 		// slashed or just have no power yet
 		return nil, nil
@@ -453,7 +471,7 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg,
 		return nil, xerrors.Errorf("scratching ticket failed: %w", err)
 	}
 
-	winner, err := gen.IsRoundWinner(ctx, base.TipSet, round, m.address, rbase, mbi, m.api)
+	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)
 	}
@@ -505,7 +523,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", b.Header.Height, "miner", b.Header.Miner, "parents", parentMiners, "took", dur)
+	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)
 	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),