diff --git a/chainio/consumer.go b/chainio/consumer.go index a9ec25745..eb059a624 100644 --- a/chainio/consumer.go +++ b/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: diff --git a/chainio/dispatcher.go b/chainio/dispatcher.go index 87bc21fba..269bb1892 100644 --- a/chainio/dispatcher.go +++ b/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) diff --git a/contractcourt/channel_arbitrator.go b/contractcourt/channel_arbitrator.go index 3b1c82ce5..cfefea457 100644 --- a/contractcourt/channel_arbitrator.go +++ b/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 { diff --git a/contractcourt/htlc_outgoing_contest_resolver.go b/contractcourt/htlc_outgoing_contest_resolver.go index b66a3fdf0..9e94587cc 100644 --- a/contractcourt/htlc_outgoing_contest_resolver.go +++ b/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 } diff --git a/lnutils/log.go b/lnutils/log.go index a32738bdf..a588bf3ce 100644 --- a/lnutils/log.go +++ b/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) + } +} diff --git a/sweep/fee_bumper.go b/sweep/fee_bumper.go index a43f87585..57f9f6e30 100644 --- a/sweep/fee_bumper.go +++ b/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 diff --git a/sweep/sweeper.go b/sweep/sweeper.go index d49f104af..88404e52a 100644 --- a/sweep/sweeper.go +++ b/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 } diff --git a/sweep/txgenerator.go b/sweep/txgenerator.go index 993ee9e59..995949b15 100644 --- a/sweep/txgenerator.go +++ b/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") } diff --git a/sweep/txgenerator_test.go b/sweep/txgenerator_test.go index 71477bd6e..3f2051646 100644 --- a/sweep/txgenerator_test.go +++ b/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)" )