From 2e85647ec467c37183bc3beb957c20e20a329394 Mon Sep 17 00:00:00 2001 From: "Johan T. Halseth" Date: Thu, 14 Nov 2019 15:25:16 +0100 Subject: [PATCH 1/5] chainntnfs/txnotifier: include script in SpendRequest string representation --- chainntnfs/txnotifier.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/chainntnfs/txnotifier.go b/chainntnfs/txnotifier.go index 8c16966f..2170b297 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 From fa40fa6950b84005ffa095fd9de0d1cbae73dd32 Mon Sep 17 00:00:00 2001 From: "Johan T. Halseth" Date: Thu, 14 Nov 2019 16:09:07 +0100 Subject: [PATCH 2/5] chainntnfs/interface: add String method for SpendDetaill --- chainntnfs/interface.go | 6 ++++++ 1 file changed, 6 insertions(+) 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. From 1c832789d62a45b242280030343d0a9a12ab6e76 Mon Sep 17 00:00:00 2001 From: "Johan T. Halseth" Date: Thu, 21 Nov 2019 15:11:40 +0100 Subject: [PATCH 3/5] chainntnfs/bitcoind: log finished hitsorical spend dispatch --- chainntnfs/bitcoindnotify/bitcoind.go | 8 ++++++++ 1 file changed, 8 insertions(+) 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 From 339543857a0b3e686ad2faca8e63d48bdd6209d3 Mon Sep 17 00:00:00 2001 From: "Johan T. Halseth" Date: Thu, 21 Nov 2019 15:13:16 +0100 Subject: [PATCH 4/5] chainntnfs/txnotifier: add more debug logs aroung spend dispatch To track down missing spends. --- chainntnfs/txnotifier.go | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/chainntnfs/txnotifier.go b/chainntnfs/txnotifier.go index 2170b297..d919f230 100644 --- a/chainntnfs/txnotifier.go +++ b/chainntnfs/txnotifier.go @@ -1245,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 } @@ -1270,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) @@ -1288,6 +1293,9 @@ 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 } @@ -1345,6 +1353,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, @@ -1386,6 +1396,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) @@ -1587,6 +1599,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 From ddeb9fbbbbcc17fe177414ad8e6cdd93e689d289 Mon Sep 17 00:00:00 2001 From: "Johan T. Halseth" Date: Thu, 21 Nov 2019 15:17:28 +0100 Subject: [PATCH 5/5] chainntnfs/txnotifier: promote historical spend log to info And add some more details. --- chainntnfs/txnotifier.go | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/chainntnfs/txnotifier.go b/chainntnfs/txnotifier.go index d919f230..94a959d5 100644 --- a/chainntnfs/txnotifier.go +++ b/chainntnfs/txnotifier.go @@ -1084,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, @@ -1299,8 +1299,9 @@ func (n *TxNotifier) dispatchSpendDetails(ntfn *SpendNtfn, details *SpendDetail) 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: