multi: optimize loggings around changes from blockbeat

chainio/consumer.go

@@ -79,7 +79,7 @@ func (b *BeatConsumer) ProcessBlock(beat Blockbeat) error {
 	// `beat.NotifyBlockProcessed` to send the error back here.
 	select {
 	case err := <-b.errChan:
-		beat.logger().Debugf("[%s] processed beat: err=%v", b.name, err)
+		beat.logger().Tracef("[%s] processed beat: err=%v", b.name, err)
 
 		return err
 
@@ -99,11 +99,11 @@ func (b *BeatConsumer) ProcessBlock(beat Blockbeat) error {
 // processing the block.
 func (b *BeatConsumer) NotifyBlockProcessed(beat Blockbeat, err error) {
 	// Update the current height.
-	beat.logger().Debugf("[%s]: notifying beat processed", b.name)
+	beat.logger().Tracef("[%s]: notifying beat processed", b.name)
 
 	select {
 	case b.errChan <- err:
-		beat.logger().Debugf("[%s]: notified beat processed, err=%v",
+		beat.logger().Tracef("[%s]: notified beat processed, err=%v",
 			b.name, err)
 
 	case <-b.quit:

chainio/dispatcher.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/btcsuite/btclog/v2"
 	"github.com/lightningnetwork/lnd/chainntnfs"
+	"github.com/lightningnetwork/lnd/lnutils"
 	"golang.org/x/sync/errgroup"
 )
 
@@ -136,6 +137,10 @@ func (b *BlockbeatDispatcher) dispatchBlocks(
 				return
 			}
 
+			// Log a separator so it's easier to identify when a
+			// new block arrives for subsystems.
+			clog.Debugf("%v", lnutils.NewSeparatorClosure())
+
 			clog.Infof("Received new block %v at height %d, "+
 				"notifying consumers...", blockEpoch.Hash,
 				blockEpoch.Height)

contractcourt/channel_arbitrator.go

@@ -479,7 +479,7 @@ func (c *ChannelArbitrator) Start(state *chanArbStartState,
 		}
 	}
 
-	log.Debugf("Starting ChannelArbitrator(%v), htlc_set=%v, state=%v",
+	log.Tracef("Starting ChannelArbitrator(%v), htlc_set=%v, state=%v",
 		c.cfg.ChanPoint, lnutils.SpewLogClosure(c.activeHTLCs),
 		state.currentState)
 
@@ -2618,14 +2618,14 @@ func (c *ChannelArbitrator) replaceResolver(oldResolver,
 func (c *ChannelArbitrator) resolveContract(currentContract ContractResolver) {
 	defer c.wg.Done()
 
-	log.Debugf("ChannelArbitrator(%v): attempting to resolve %T",
+	log.Tracef("ChannelArbitrator(%v): attempting to resolve %T",
 		c.cfg.ChanPoint, currentContract)
 
 	// Until the contract is fully resolved, we'll continue to iteratively
 	// resolve the contract one step at a time.
 	for !currentContract.IsResolved() {
-		log.Debugf("ChannelArbitrator(%v): contract %T not yet resolved",
-			c.cfg.ChanPoint, currentContract)
+		log.Tracef("ChannelArbitrator(%v): contract %T not yet "+
+			"resolved", c.cfg.ChanPoint, currentContract)
 
 		select {
 

contractcourt/htlc_outgoing_contest_resolver.go

@@ -165,9 +165,8 @@ func (h *htlcOutgoingContestResolver) Resolve() (ContractResolver, error) {
 			if newHeight >= expiry-1 {
 				h.log.Infof("HTLC about to expire "+
 					"(height=%v, expiry=%v), transforming "+
-					"into timeout resolver", h,
-					h.htlcResolution.ClaimOutpoint,
-					newHeight, h.htlcResolution.Expiry)
+					"into timeout resolver", newHeight,
+					h.htlcResolution.Expiry)
 
 				return h.htlcTimeoutResolver, nil
 			}

lnutils/log.go

@@ -1,6 +1,10 @@
 package lnutils
 
-import "github.com/davecgh/go-spew/spew"
+import (
+	"strings"
+
+	"github.com/davecgh/go-spew/spew"
+)
 
 // LogClosure is used to provide a closure over expensive logging operations so
 // don't have to be performed when the logging level doesn't warrant it.
@@ -25,3 +29,10 @@ func SpewLogClosure(a any) LogClosure {
 		return spew.Sdump(a)
 	}
 }
+
+// NewSeparatorClosure returns a new closure that logs a separator line.
+func NewSeparatorClosure() LogClosure {
+	return func() string {
+		return strings.Repeat("=", 80)
+	}
+}

sweep/fee_bumper.go

@@ -1588,7 +1588,10 @@ func prepareSweepTx(inputs []input.Input, changePkScript lnwallet.AddrWithKey,
 
 		// Check if the lock time has reached
 		if lt > uint32(currentHeight) {
-			return 0, noChange, noLocktime, ErrLocktimeImmature
+			return 0, noChange, noLocktime,
+				fmt.Errorf("%w: current height is %v, "+
+					"locktime is %v", ErrLocktimeImmature,
+					currentHeight, lt)
 		}
 
 		// If another input commits to a different locktime, they

sweep/sweeper.go

@@ -229,7 +229,7 @@ func (p *SweeperInput) isMature(currentHeight uint32) (bool, uint32) {
 	locktime, _ := p.RequiredLockTime()
 	if currentHeight < locktime {
 		log.Debugf("Input %v has locktime=%v, current height is %v",
-			p.OutPoint(), locktime, currentHeight)
+			p, locktime, currentHeight)
 
 		return false, locktime
 	}
@@ -243,8 +243,7 @@ func (p *SweeperInput) isMature(currentHeight uint32) (bool, uint32) {
 	locktime = p.BlocksToMaturity() + p.HeightHint()
 	if currentHeight+1 < locktime {
 		log.Debugf("Input %v has CSV expiry=%v, current height is %v, "+
-			"skipped sweeping", p.OutPoint(), locktime,
-			currentHeight)
+			"skipped sweeping", p, locktime, currentHeight)
 
 		return false, locktime
 	}
@@ -255,6 +254,21 @@ func (p *SweeperInput) isMature(currentHeight uint32) (bool, uint32) {
 // InputsMap is a type alias for a set of pending inputs.
 type InputsMap = map[wire.OutPoint]*SweeperInput
 
+// inputsMapToString returns a human readable interpretation of the pending
+// inputs.
+func inputsMapToString(inputs InputsMap) string {
+	if len(inputs) == 0 {
+		return ""
+	}
+
+	inps := make([]input.Input, 0, len(inputs))
+	for _, in := range inputs {
+		inps = append(inps, in)
+	}
+
+	return "\n" + inputTypeSummary(inps)
+}
+
 // pendingSweepsReq is an internal message we'll use to represent an external
 // caller's intent to retrieve all of the pending inputs the UtxoSweeper is
 // attempting to sweep.
@@ -700,17 +714,10 @@ func (s *UtxoSweeper) collector() {
 			inputs := s.updateSweeperInputs()
 
 			log.Debugf("Received new block: height=%v, attempt "+
-				"sweeping %d inputs:\n%s",
-				s.currentHeight, len(inputs),
+				"sweeping %d inputs:%s", s.currentHeight,
+				len(inputs),
 				lnutils.NewLogClosure(func() string {
-					inps := make(
-						[]input.Input, 0, len(inputs),
-					)
-					for _, in := range inputs {
-						inps = append(inps, in)
-					}
-
-					return inputTypeSummary(inps)
+					return inputsMapToString(inputs)
 				}))
 
 			// Attempt to sweep any pending inputs.
@@ -1244,10 +1251,10 @@ func (s *UtxoSweeper) handleNewInput(input *sweepInputMessage) error {
 	log.Tracef("input %v, state=%v, added to inputs", outpoint, pi.state)
 
 	log.Infof("Registered sweep request at block %d: out_point=%v, "+
-		"witness_type=%v, amount=%v, deadline=%d, params=(%v)",
-		s.currentHeight, pi.OutPoint(), pi.WitnessType(),
+		"witness_type=%v, amount=%v, deadline=%d, state=%v, "+
+		"params=(%v)", s.currentHeight, pi.OutPoint(), pi.WitnessType(),
 		btcutil.Amount(pi.SignDesc().Output.Value), pi.DeadlineHeight,
-		pi.params)
+		pi.state, pi.params)
 
 	// Start watching for spend of this input, either by us or the remote
 	// party.
@@ -1523,12 +1530,8 @@ func (s *UtxoSweeper) updateSweeperInputs() InputsMap {
 
 		// If the input has a locktime that's not yet reached, we will
 		// skip this input and wait for the locktime to be reached.
-		mature, locktime := input.isMature(uint32(s.currentHeight))
+		mature, _ := input.isMature(uint32(s.currentHeight))
 		if !mature {
-			log.Debugf("Skipping input %v due to locktime=%v not "+
-				"reached, current height is %v", op, locktime,
-				s.currentHeight)
-
 			continue
 		}
 

sweep/txgenerator.go

@@ -315,5 +315,6 @@ func inputTypeSummary(inputs []input.Input) string {
 		part := fmt.Sprintf("%v (%v)", i.OutPoint(), i.WitnessType())
 		parts = append(parts, part)
 	}
-	return strings.Join(parts, ", ")
+
+	return strings.Join(parts, "\n")
 }

sweep/txgenerator_test.go

@@ -16,10 +16,12 @@ var (
 		input.HtlcOfferedRemoteTimeout,
 		input.WitnessKeyHash,
 	}
-	expectedWeight  = int64(1460)
-	expectedSummary = "0000000000000000000000000000000000000000000000000000000000000000:10 (CommitmentTimeLock), " +
-		"0000000000000000000000000000000000000000000000000000000000000001:11 (HtlcAcceptedSuccessSecondLevel), " +
-		"0000000000000000000000000000000000000000000000000000000000000002:12 (HtlcOfferedRemoteTimeout), " +
+	expectedWeight = int64(1460)
+
+	//nolint:ll
+	expectedSummary = "0000000000000000000000000000000000000000000000000000000000000000:10 (CommitmentTimeLock)\n" +
+		"0000000000000000000000000000000000000000000000000000000000000001:11 (HtlcAcceptedSuccessSecondLevel)\n" +
+		"0000000000000000000000000000000000000000000000000000000000000002:12 (HtlcOfferedRemoteTimeout)\n" +
 		"0000000000000000000000000000000000000000000000000000000000000003:13 (WitnessKeyHash)"
 )