Merge pull request #3752 from halseth/chainntfs-spendntfn-logs

[chainntnfs] add more logging for spend requests

chainntnfs/bitcoindnotify/bitcoind.go

@@ -262,6 +262,14 @@ out:
 						return
 					}
 
+					chainntnfs.Log.Infof("Historical "+
+						"spend dispatch finished"+
+						"for request %v (start=%v "+
+						"end=%v) with details: %v",
+						msg.SpendRequest,
+						msg.StartHeight, msg.EndHeight,
+						spendDetails)
+
 					// If the historical dispatch finished
 					// without error, we will invoke
 					// UpdateSpendDetails even if none were

chainntnfs/interface.go

@@ -241,6 +241,12 @@ type SpendDetail struct {
 	SpendingHeight    int32
 }
 
+// String returns a string representation of SpendDetail.
+func (s *SpendDetail) String() string {
+	return fmt.Sprintf("%v[%d] spending %v at height=%v", s.SpenderTxHash,
+		s.SpenderInputIndex, s.SpentOutPoint, s.SpendingHeight)
+}
+
 // SpendEvent encapsulates a spentness notification. Its only field 'Spend' will
 // be sent upon once the target output passed into RegisterSpendNtfn has been
 // spent on the blockchain.

chainntnfs/txnotifier.go

@@ -328,9 +328,10 @@ func NewSpendRequest(op *wire.OutPoint, pkScript []byte) (SpendRequest, error) {
 // String returns the string representation of the SpendRequest.
 func (r SpendRequest) String() string {
 	if r.OutPoint != ZeroOutPoint {
-		return fmt.Sprintf("outpoint=%v", r.OutPoint)
+		return fmt.Sprintf("outpoint=%v, script=%v", r.OutPoint,
+			r.PkScript)
 	}
-	return fmt.Sprintf("script=%v", r.PkScript)
+	return fmt.Sprintf("outpoint=<zero>, script=%v", r.PkScript)
 }
 
 // SpendHintKey returns the key that will be used to index the spend request's
@@ -1083,8 +1084,8 @@ func (n *TxNotifier) RegisterSpend(outpoint *wire.OutPoint, pkScript []byte,
 	// notifications don't also attempt a historical dispatch.
 	spendSet.rescanStatus = rescanPending
 
-	Log.Debugf("Dispatching historical spend rescan for %v",
+	Log.Infof("Dispatching historical spend rescan for %v, start=%d, "+
-		ntfn.SpendRequest)
+		"end=%d", ntfn.SpendRequest, startHeight, n.currentHeight)
 
 	return &SpendRegistration{
 		Event: ntfn.Event,
@@ -1244,6 +1245,8 @@ func (n *TxNotifier) updateSpendDetails(spendRequest SpendRequest,
 				n.currentHeight, spendRequest, err)
 		}
 
+		Log.Debugf("Updated spend hint to height=%v for unconfirmed "+
+			"spend request %v", n.currentHeight, spendRequest)
 		return nil
 	}
 
@@ -1269,6 +1272,9 @@ func (n *TxNotifier) updateSpendDetails(spendRequest SpendRequest,
 			details.SpendingHeight, spendRequest, err)
 	}
 
+	Log.Debugf("Updated spend hint to height=%v for confirmed spend "+
+		"request %v", details.SpendingHeight, spendRequest)
+
 	spendSet.details = details
 	for _, ntfn := range spendSet.ntfns {
 		err := n.dispatchSpendDetails(ntfn, spendSet.details)
@@ -1287,11 +1293,15 @@ func (n *TxNotifier) dispatchSpendDetails(ntfn *SpendNtfn, details *SpendDetail)
 	// If there are no spend details to dispatch or if the notification has
 	// already been dispatched, then we can skip dispatching to this client.
 	if details == nil || ntfn.dispatched {
+		Log.Debugf("Skipping dispatch of spend details(%v) for "+
+			"request %v, dispatched=%v", details, ntfn.SpendRequest,
+			ntfn.dispatched)
 		return nil
 	}
 
-	Log.Infof("Dispatching confirmed spend notification for %v at height=%d",
+	Log.Infof("Dispatching confirmed spend notification for %v at "+
-		ntfn.SpendRequest, n.currentHeight)
+		"current height=%d: %v", ntfn.SpendRequest, n.currentHeight,
+		details)
 
 	select {
 	case ntfn.Event.Spend <- details:
@@ -1344,6 +1354,8 @@ func (n *TxNotifier) ConnectTip(blockHash *chainhash.Hash, blockHeight uint32,
 
 	// First, we'll iterate over all the transactions found in this block to
 	// determine if it includes any relevant transactions to the TxNotifier.
+	Log.Debugf("Filtering %d txns for %d spend requests at height %d",
+		len(txns), len(n.spendNotifications), blockHeight)
 	for _, tx := range txns {
 		n.filterTx(
 			tx, blockHash, blockHeight, n.handleConfDetailsAtTip,
@@ -1385,6 +1397,8 @@ func (n *TxNotifier) ConnectTip(blockHash *chainhash.Hash, blockHeight uint32,
 				}
 			}
 
+			Log.Debugf("Deleting mature spend request %v at "+
+				"height=%d", spendRequest, blockHeight)
 			delete(n.spendNotifications, spendRequest)
 		}
 		delete(n.spendsByHeight, matureBlockHeight)
@@ -1586,6 +1600,9 @@ func (n *TxNotifier) handleSpendDetailsAtTip(spendRequest SpendRequest,
 		n.spendsByHeight[spendHeight] = opSet
 	}
 	opSet[spendRequest] = struct{}{}
+
+	Log.Debugf("Spend request %v spent at tip=%d", spendRequest,
+		spendHeight)
 }
 
 // NotifyHeight dispatches confirmation and spend notifications to the clients