multi: add more logging when fetching invoices and payments.

channeldb/invoices.go

@@ -142,6 +142,10 @@ const (
 	ampStateSettleDateType  tlv.Type = 3
 	ampStateCircuitKeysType tlv.Type = 4
 	ampStateAmtPaidType     tlv.Type = 5
+
+	// invoiceScanBatchSize is the number we use limiting the logging output
+	// of invoice processing.
+	invoiceScanBatchSize = 1000
 )
 
 // AddInvoice inserts the targeted invoice into the database. If the invoice has
@@ -241,7 +245,11 @@ func (d *DB) AddInvoice(_ context.Context, newInvoice *invpkg.Invoice,
 func (d *DB) InvoicesAddedSince(_ context.Context, sinceAddIndex uint64) (
 	[]invpkg.Invoice, error) {
 
-	var newInvoices []invpkg.Invoice
+	var (
+		newInvoices    []invpkg.Invoice
+		start          = time.Now()
+		processedCount int
+	)
 
 	// If an index of zero was specified, then in order to maintain
 	// backwards compat, we won't send out any new invoices.
@@ -274,7 +282,6 @@ func (d *DB) InvoicesAddedSince(_ context.Context, sinceAddIndex uint64) (
 		addSeqNo, invoiceKey := invoiceCursor.Next()
 
 		for ; addSeqNo != nil && bytes.Compare(addSeqNo, startIndex[:]) > 0; addSeqNo, invoiceKey = invoiceCursor.Next() {
-
 			// For each key found, we'll look up the actual
 			// invoice, then accumulate it into our return value.
 			invoice, err := fetchInvoice(
@@ -285,6 +292,13 @@ func (d *DB) InvoicesAddedSince(_ context.Context, sinceAddIndex uint64) (
 			}
 
 			newInvoices = append(newInvoices, invoice)
+
+			processedCount++
+			if processedCount%invoiceScanBatchSize == 0 {
+				log.Debugf("Processed %d invoices since "+
+					"invoice with add index %v",
+					processedCount, sinceAddIndex)
+			}
 		}
 
 		return nil
@@ -295,6 +309,12 @@ func (d *DB) InvoicesAddedSince(_ context.Context, sinceAddIndex uint64) (
 		return nil, err
 	}
 
+	elapsed := time.Since(start)
+	log.Debugf("Completed scanning invoices added since index %v: "+
+		"total_processed=%d, found_invoices=%d, elapsed=%v",
+		sinceAddIndex, processedCount, len(newInvoices),
+		elapsed.Round(time.Millisecond))
+
 	return newInvoices, nil
 }
 
@@ -1045,7 +1065,11 @@ func (k *kvInvoiceUpdater) serializeAndStoreInvoice() error {
 func (d *DB) InvoicesSettledSince(_ context.Context, sinceSettleIndex uint64) (
 	[]invpkg.Invoice, error) {
 
-	var settledInvoices []invpkg.Invoice
+	var (
+		settledInvoices []invpkg.Invoice
+		start           = time.Now()
+		processedCount  int
+	)
 
 	// If an index of zero was specified, then in order to maintain
 	// backwards compat, we won't send out any new invoices.
@@ -1104,6 +1128,13 @@ func (d *DB) InvoicesSettledSince(_ context.Context, sinceSettleIndex uint64) (
 			}
 
 			settledInvoices = append(settledInvoices, invoice)
+
+			processedCount++
+			if processedCount%invoiceScanBatchSize == 0 {
+				log.Debugf("Processed %d settled invoices "+
+					"since invoice with settle index %v",
+					processedCount, sinceSettleIndex)
+			}
 		}
 
 		return nil
@@ -1114,6 +1145,12 @@ func (d *DB) InvoicesSettledSince(_ context.Context, sinceSettleIndex uint64) (
 		return nil, err
 	}
 
+	elapsed := time.Since(start)
+	log.Debugf("Completed scanning invoices settled since index %v: "+
+		"total_processed=%d, found_invoices=%d, elapsed=%v",
+		sinceSettleIndex, processedCount, len(settledInvoices),
+		elapsed.Round(time.Millisecond))
+
 	return settledInvoices, nil
 }
 

channeldb/payment_control.go

@@ -7,6 +7,7 @@ import (
 	"fmt"
 	"io"
 	"sync"
+	"time"
 
 	"github.com/lightningnetwork/lnd/kvdb"
 	"github.com/lightningnetwork/lnd/lntypes"
@@ -16,6 +17,10 @@ const (
 	// paymentSeqBlockSize is the block size used when we batch allocate
 	// payment sequences for future payments.
 	paymentSeqBlockSize = 1000
+
+	// paymentBatchSize is the number we use limiting the logging output
+	// of payment processing.
+	paymentBatchSize = 1000
 )
 
 var (
@@ -770,7 +775,12 @@ func fetchPaymentStatus(bucket kvdb.RBucket) (PaymentStatus, error) {
 
 // FetchInFlightPayments returns all payments with status InFlight.
 func (p *PaymentControl) FetchInFlightPayments() ([]*MPPayment, error) {
-	var inFlights []*MPPayment
+	var (
+		inFlights      []*MPPayment
+		start          = time.Now()
+		processedCount int
+	)
+
 	err := kvdb.View(p.db, func(tx kvdb.RTx) error {
 		payments := tx.ReadBucket(paymentsRootBucket)
 		if payments == nil {
@@ -788,6 +798,14 @@ func (p *PaymentControl) FetchInFlightPayments() ([]*MPPayment, error) {
 				return err
 			}
 
+			processedCount++
+			if processedCount%paymentBatchSize == 0 {
+				log.Debugf("Scanning inflight payments "+
+					"(in progress), processed %d, last "+
+					"processed payment: %v", processedCount,
+					p.Info)
+			}
+
 			// Skip the payment if it's terminated.
 			if p.Terminated() {
 				return nil
@@ -803,5 +821,10 @@ func (p *PaymentControl) FetchInFlightPayments() ([]*MPPayment, error) {
 		return nil, err
 	}
 
+	elapsed := time.Since(start)
+	log.Debugf("Completed scanning inflight payments: total_processed=%d, "+
+		"found_inflight=%d, elapsed=%v", processedCount, len(inFlights),
+		elapsed.Round(time.Millisecond))
+
 	return inFlights, nil
 }

channeldb/payments.go

@@ -202,6 +202,12 @@ type PaymentCreationInfo struct {
 	FirstHopCustomRecords lnwire.CustomRecords
 }
 
+func (p *PaymentCreationInfo) String() string {
+	return fmt.Sprintf("payment_id=%v, amount=%v, created_at=%v, "+
+		"payment_request=%v", p.PaymentIdentifier, p.Value,
+		p.CreationTime, p.PaymentRequest)
+}
+
 // htlcBucketKey creates a composite key from prefix and id where the result is
 // simply the two concatenated.
 func htlcBucketKey(prefix, id []byte) []byte {