diff --git a/chainntnfs/bitcoindnotify/bitcoind.go b/chainntnfs/bitcoindnotify/bitcoind.go index 850b63e6..7bf61716 100644 --- a/chainntnfs/bitcoindnotify/bitcoind.go +++ b/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 diff --git a/chainntnfs/interface.go b/chainntnfs/interface.go index 88a389dd..ace86e77 100644 --- a/chainntnfs/interface.go +++ b/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. diff --git a/chainntnfs/txnotifier.go b/chainntnfs/txnotifier.go index 8c16966f..94a959d5 100644 --- a/chainntnfs/txnotifier.go +++ b/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=, 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", - ntfn.SpendRequest) + Log.Infof("Dispatching historical spend rescan for %v, start=%d, "+ + "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", - ntfn.SpendRequest, n.currentHeight) + Log.Infof("Dispatching confirmed spend notification for %v at "+ + "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