sweep: improve loggings based on feedback

This commit changes the logging levels and add a few more loggings based
on the testing results from the testnet/mainnet.

chainntnfs/txnotifier.go

@@ -772,8 +772,8 @@ func (n *TxNotifier) CancelConf(confRequest ConfRequest, confID uint64) {
 		return
 	}
 
-	Log.Infof("Canceling confirmation notification: conf_id=%d, %v", confID,
-		confRequest)
+	Log.Debugf("Canceling confirmation notification: conf_id=%d, %v",
+		confID, confRequest)
 
 	// We'll close all the notification channels to let the client know
 	// their cancel request has been fulfilled.
@@ -925,7 +925,7 @@ func (n *TxNotifier) dispatchConfDetails(
 	// we'll dispatch a confirmation notification to the caller.
 	confHeight := details.BlockHeight + ntfn.NumConfirmations - 1
 	if confHeight <= n.currentHeight {
-		Log.Infof("Dispatching %v confirmation notification for %v",
+		Log.Debugf("Dispatching %v confirmation notification for %v",
 			ntfn.NumConfirmations, ntfn.ConfRequest)
 
 		// We'll send a 0 value to the Updates channel,
@@ -1058,7 +1058,7 @@ func (n *TxNotifier) RegisterSpend(outpoint *wire.OutPoint, pkScript []byte,
 	n.Lock()
 	defer n.Unlock()
 
-	Log.Infof("New spend subscription: spend_id=%d, %v, height_hint=%d",
+	Log.Debugf("New spend subscription: spend_id=%d, %v, height_hint=%d",
 		ntfn.SpendID, ntfn.SpendRequest, startHeight)
 
 	// Keep track of the notification request so that we can properly
@@ -1136,7 +1136,7 @@ func (n *TxNotifier) RegisterSpend(outpoint *wire.OutPoint, pkScript []byte,
 	// notifications don't also attempt a historical dispatch.
 	spendSet.rescanStatus = rescanPending
 
-	Log.Infof("Dispatching historical spend rescan for %v, start=%d, "+
+	Log.Debugf("Dispatching historical spend rescan for %v, start=%d, "+
 		"end=%d", ntfn.SpendRequest, startHeight, n.currentHeight)
 
 	return &SpendRegistration{
@@ -1171,7 +1171,7 @@ func (n *TxNotifier) CancelSpend(spendRequest SpendRequest, spendID uint64) {
 		return
 	}
 
-	Log.Infof("Canceling spend notification: spend_id=%d, %v", spendID,
+	Log.Debugf("Canceling spend notification: spend_id=%d, %v", spendID,
 		spendRequest)
 
 	// We'll close all the notification channels to let the client know
@@ -1364,7 +1364,7 @@ func (n *TxNotifier) dispatchSpendDetails(ntfn *SpendNtfn, details *SpendDetail)
 		return nil
 	}
 
-	Log.Infof("Dispatching confirmed spend notification for %v at "+
+	Log.Debugf("Dispatching confirmed spend notification for %v at "+
 		"current height=%d: %v", ntfn.SpendRequest, n.currentHeight,
 		details)
 
@@ -1743,7 +1743,7 @@ func (n *TxNotifier) NotifyHeight(height uint32) error {
 	for ntfn := range n.ntfnsByConfirmHeight[height] {
 		confSet := n.confNotifications[ntfn.ConfRequest]
 
-		Log.Infof("Dispatching %v confirmation notification for %v",
+		Log.Debugf("Dispatching %v confirmation notification for %v",
 			ntfn.NumConfirmations, ntfn.ConfRequest)
 
 		// The default notification we assigned above includes the

sweep/sweeper.go

@@ -767,11 +767,11 @@ func (s *UtxoSweeper) signalResult(pi *SweeperInput, result Result) {
 	listeners := pi.listeners
 
 	if result.Err == nil {
-		log.Debugf("Dispatching sweep success for %v to %v listeners",
+		log.Tracef("Dispatching sweep success for %v to %v listeners",
 			op, len(listeners),
 		)
 	} else {
-		log.Debugf("Dispatching sweep error for %v to %v listeners: %v",
+		log.Tracef("Dispatching sweep error for %v to %v listeners: %v",
 			op, len(listeners), result.Err,
 		)
 	}
@@ -830,6 +830,9 @@ func (s *UtxoSweeper) sweep(set InputSet) error {
 			outpoints[i] = inp.OutPoint()
 		}
 
+		log.Errorf("Initial broadcast failed: %v, inputs=\n%v", err,
+			inputTypeSummary(set.Inputs()))
+
 		// TODO(yy): find out which input is causing the failure.
 		s.markInputsPublishFailed(outpoints)
 
@@ -855,7 +858,7 @@ func (s *UtxoSweeper) markInputsPendingPublish(set InputSet) {
 			// It could be that this input is an additional wallet
 			// input that was attached. In that case there also
 			// isn't a pending input to update.
-			log.Debugf("Skipped marking input as pending "+
+			log.Tracef("Skipped marking input as pending "+
 				"published: %v not found in pending inputs",
 				input.OutPoint())
 
@@ -904,7 +907,7 @@ func (s *UtxoSweeper) markInputsPublished(tr *TxRecord,
 			// It could be that this input is an additional wallet
 			// input that was attached. In that case there also
 			// isn't a pending input to update.
-			log.Debugf("Skipped marking input as published: %v "+
+			log.Tracef("Skipped marking input as published: %v "+
 				"not found in pending inputs",
 				input.PreviousOutPoint)
 
@@ -940,7 +943,7 @@ func (s *UtxoSweeper) markInputsPublishFailed(outpoints []wire.OutPoint) {
 			// It could be that this input is an additional wallet
 			// input that was attached. In that case there also
 			// isn't a pending input to update.
-			log.Debugf("Skipped marking input as publish failed: "+
+			log.Tracef("Skipped marking input as publish failed: "+
 				"%v not found in pending inputs", op)
 
 			continue
@@ -948,7 +951,7 @@ func (s *UtxoSweeper) markInputsPublishFailed(outpoints []wire.OutPoint) {
 
 		// Valdiate that the input is in an expected state.
 		if pi.state != PendingPublish && pi.state != Published {
-			log.Errorf("Expect input %v to have %v, instead it "+
+			log.Debugf("Expect input %v to have %v, instead it "+
 				"has %v", op, PendingPublish, pi.state)
 
 			continue
@@ -1397,7 +1400,7 @@ func (s *UtxoSweeper) markInputsSwept(tx *wire.MsgTx, isOurTx bool) {
 		if !ok {
 			// It's very likely that a spending tx contains inputs
 			// that we don't know.
-			log.Debugf("Skipped marking input as swept: %v not "+
+			log.Tracef("Skipped marking input as swept: %v not "+
 				"found in pending inputs", outpoint)
 
 			continue

sweep/sweeper_test.go

@@ -695,12 +695,12 @@ func TestSweepPendingInputs(t *testing.T) {
 
 	// Mock the methods used in `sweep`. This is not important for this
 	// unit test.
-	setNeedWallet.On("Inputs").Return(nil).Times(4)
+	setNeedWallet.On("Inputs").Return(nil).Maybe()
 	setNeedWallet.On("DeadlineHeight").Return(testHeight).Once()
 	setNeedWallet.On("Budget").Return(btcutil.Amount(1)).Once()
 	setNeedWallet.On("StartingFeeRate").Return(
 		fn.None[chainfee.SatPerKWeight]()).Once()
-	normalSet.On("Inputs").Return(nil).Times(4)
+	normalSet.On("Inputs").Return(nil).Maybe()
 	normalSet.On("DeadlineHeight").Return(testHeight).Once()
 	normalSet.On("Budget").Return(btcutil.Amount(1)).Once()
 	normalSet.On("StartingFeeRate").Return(

sweep/tx_input_set.go

@@ -241,13 +241,13 @@ func (b *BudgetInputSet) NeedWalletInput() bool {
 		// If the input's budget is not even covered by itself, we need
 		// to borrow outputs from other inputs.
 		if budgetBorrowable < 0 {
-			log.Debugf("Input %v specified a budget that exceeds "+
+			log.Tracef("Input %v specified a budget that exceeds "+
 				"its output value: %v > %v", inp, budget,
 				output)
 		}
 	}
 
-	log.Tracef("NeedWalletInput: budgetNeeded=%v, budgetBorrowable=%v",
+	log.Debugf("NeedWalletInput: budgetNeeded=%v, budgetBorrowable=%v",
 		budgetNeeded, budgetBorrowable)
 
 	// If we don't have enough extra budget to borrow, we need wallet
@@ -314,6 +314,8 @@ func (b *BudgetInputSet) AddWalletInputs(wallet Wallet) error {
 		}
 		b.addInput(pi)
 
+		log.Debugf("Added wallet input %v to input set", pi)
+
 		// Return if we've reached the minimum output amount.
 		if !b.NeedWalletInput() {
 			return nil