Merge pull request #9749 from ziggie1984/fix-logging-invoices-payments

mulit: increase logprogress time

channeldb/invoices.go

@@ -143,9 +143,9 @@ const (
 	ampStateCircuitKeysType tlv.Type = 4
 	ampStateAmtPaidType     tlv.Type = 5
 
-	// invoiceScanBatchSize is the number we use limiting the logging output
-	// of invoice processing.
-	invoiceScanBatchSize = 1000
+	// invoiceProgressLogInterval is the interval we use limiting the
+	// logging output of invoice processing.
+	invoiceProgressLogInterval = 30 * time.Second
 )
 
 // AddInvoice inserts the targeted invoice into the database. If the invoice has
@@ -248,6 +248,7 @@ func (d *DB) InvoicesAddedSince(_ context.Context, sinceAddIndex uint64) (
 	var (
 		newInvoices    []invpkg.Invoice
 		start          = time.Now()
+		lastLogTime    = time.Now()
 		processedCount int
 	)
 
@@ -294,10 +295,14 @@ 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",
+			if time.Since(lastLogTime) >=
+				invoiceProgressLogInterval {
+
+				log.Debugf("Processed %d invoices which "+
+					"were added since add index %v",
 					processedCount, sinceAddIndex)
+
+				lastLogTime = time.Now()
 			}
 		}
 
@@ -310,7 +315,7 @@ func (d *DB) InvoicesAddedSince(_ context.Context, sinceAddIndex uint64) (
 	}
 
 	elapsed := time.Since(start)
-	log.Debugf("Completed scanning invoices added since index %v: "+
+	log.Debugf("Completed scanning for invoices added since index %v: "+
 		"total_processed=%d, found_invoices=%d, elapsed=%v",
 		sinceAddIndex, processedCount, len(newInvoices),
 		elapsed.Round(time.Millisecond))
@@ -1068,6 +1073,7 @@ func (d *DB) InvoicesSettledSince(_ context.Context, sinceSettleIndex uint64) (
 	var (
 		settledInvoices []invpkg.Invoice
 		start           = time.Now()
+		lastLogTime     = time.Now()
 		processedCount  int
 	)
 
@@ -1130,10 +1136,15 @@ func (d *DB) InvoicesSettledSince(_ context.Context, sinceSettleIndex uint64) (
 			settledInvoices = append(settledInvoices, invoice)
 
 			processedCount++
-			if processedCount%invoiceScanBatchSize == 0 {
+			if time.Since(lastLogTime) >=
+				invoiceProgressLogInterval {
+
 				log.Debugf("Processed %d settled invoices "+
-					"since invoice with settle index %v",
-					processedCount, sinceSettleIndex)
+					"which have a settle index greater "+
+					"than %v", processedCount,
+					sinceSettleIndex)
+
+				lastLogTime = time.Now()
 			}
 		}
 
@@ -1146,8 +1157,8 @@ func (d *DB) InvoicesSettledSince(_ context.Context, sinceSettleIndex uint64) (
 	}
 
 	elapsed := time.Since(start)
-	log.Debugf("Completed scanning invoices settled since index %v: "+
-		"total_processed=%d, found_invoices=%d, elapsed=%v",
+	log.Debugf("Completed scanning for settled invoices starting at "+
+		"index %v: total_processed=%d, found_invoices=%d, elapsed=%v",
 		sinceSettleIndex, processedCount, len(settledInvoices),
 		elapsed.Round(time.Millisecond))
 

channeldb/payment_control.go

@@ -18,9 +18,9 @@ const (
 	// payment sequences for future payments.
 	paymentSeqBlockSize = 1000
 
-	// paymentBatchSize is the number we use limiting the logging output
-	// of payment processing.
-	paymentBatchSize = 1000
+	// paymentProgressLogInterval is the interval we use limiting the
+	// logging output of payment processing.
+	paymentProgressLogInterval = 30 * time.Second
 )
 
 var (
@@ -778,6 +778,7 @@ func (p *PaymentControl) FetchInFlightPayments() ([]*MPPayment, error) {
 	var (
 		inFlights      []*MPPayment
 		start          = time.Now()
+		lastLogTime    = time.Now()
 		processedCount int
 	)
 
@@ -799,11 +800,15 @@ func (p *PaymentControl) FetchInFlightPayments() ([]*MPPayment, error) {
 			}
 
 			processedCount++
-			if processedCount%paymentBatchSize == 0 {
+			if time.Since(lastLogTime) >=
+				paymentProgressLogInterval {
+
 				log.Debugf("Scanning inflight payments "+
 					"(in progress), processed %d, last "+
 					"processed payment: %v", processedCount,
 					p.Info)
+
+				lastLogTime = time.Now()
 			}
 
 			// Skip the payment if it's terminated.
@@ -822,8 +827,9 @@ func (p *PaymentControl) FetchInFlightPayments() ([]*MPPayment, error) {
 	}
 
 	elapsed := time.Since(start)
-	log.Debugf("Completed scanning inflight payments: total_processed=%d, "+
-		"found_inflight=%d, elapsed=%v", processedCount, len(inFlights),
+	log.Debugf("Completed scanning for inflight payments: "+
+		"total_processed=%d, found_inflight=%d, elapsed=%v",
+		processedCount, len(inFlights),
 		elapsed.Round(time.Millisecond))
 
 	return inFlights, nil

channeldb/payments.go

@@ -202,10 +202,10 @@ type PaymentCreationInfo struct {
 	FirstHopCustomRecords lnwire.CustomRecords
 }
 
+// String returns a human-readable description of the payment creation info.
 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)
+	return fmt.Sprintf("payment_id=%v, amount=%v, created_at=%v",
+		p.PaymentIdentifier, p.Value, p.CreationTime)
 }
 
 // htlcBucketKey creates a composite key from prefix and id where the result is

invoices/sql_store.go

@@ -25,9 +25,9 @@ const (
 	// queries to limit the number of rows returned.
 	defaultQueryPaginationLimit = 100
 
-	// invoiceScanBatchSize is the number we use limiting the logging output
-	// when scanning invoices.
-	invoiceScanBatchSize = 1000
+	// invoiceProgressLogInterval is the interval we use limiting the
+	// logging output of invoice processing.
+	invoiceProgressLogInterval = 30 * time.Second
 )
 
 // SQLInvoiceQueries is an interface that defines the set of operations that can
@@ -792,6 +792,7 @@ func (i *SQLStore) InvoicesSettledSince(ctx context.Context, idx uint64) (
 	var (
 		invoices       []Invoice
 		start          = time.Now()
+		lastLogTime    = time.Now()
 		processedCount int
 	)
 
@@ -829,11 +830,15 @@ func (i *SQLStore) InvoicesSettledSince(ctx context.Context, idx uint64) (
 				invoices = append(invoices, *invoice)
 
 				processedCount++
-				if processedCount%invoiceScanBatchSize == 0 {
+				if time.Since(lastLogTime) >=
+					invoiceProgressLogInterval {
+
 					log.Debugf("Processed %d settled "+
-						"invoices since invoice with "+
-						"settle index %v",
+						"invoices which have a settle "+
+						"index greater than %v",
 						processedCount, idx)
+
+					lastLogTime = time.Now()
 				}
 			}
 
@@ -891,10 +896,15 @@ func (i *SQLStore) InvoicesSettledSince(ctx context.Context, idx uint64) (
 			invoices = append(invoices, *invoice)
 
 			processedCount++
-			if processedCount%invoiceScanBatchSize == 0 {
+			if time.Since(lastLogTime) >=
+				invoiceProgressLogInterval {
+
 				log.Debugf("Processed %d settled invoices "+
-					"since invoice with settle index %v",
+					"including AMP sub invoices which "+
+					"have a settle index greater than %v",
 					processedCount, idx)
+
+				lastLogTime = time.Now()
 			}
 		}
 
@@ -908,8 +918,8 @@ func (i *SQLStore) InvoicesSettledSince(ctx context.Context, idx uint64) (
 	}
 
 	elapsed := time.Since(start)
-	log.Debugf("Completed scanning invoices settled since index %v: "+
-		"total_processed=%d, found_invoices=%d, elapsed=%v",
+	log.Debugf("Completed scanning for settled invoices starting at "+
+		"index %v: total_processed=%d, found_invoices=%d, elapsed=%v",
 		idx, processedCount, len(invoices),
 		elapsed.Round(time.Millisecond))
 
@@ -928,6 +938,7 @@ func (i *SQLStore) InvoicesAddedSince(ctx context.Context, idx uint64) (
 	var (
 		result         []Invoice
 		start          = time.Now()
+		lastLogTime    = time.Now()
 		processedCount int
 	)
 
@@ -963,10 +974,14 @@ func (i *SQLStore) InvoicesAddedSince(ctx context.Context, idx uint64) (
 				result = append(result, *invoice)
 
 				processedCount++
-				if processedCount%invoiceScanBatchSize == 0 {
+				if time.Since(lastLogTime) >=
+					invoiceProgressLogInterval {
+
 					log.Debugf("Processed %d invoices "+
-						"added since invoice with add "+
+						"which were added since add "+
 						"index %v", processedCount, idx)
+
+					lastLogTime = time.Now()
 				}
 			}
 
@@ -982,7 +997,7 @@ func (i *SQLStore) InvoicesAddedSince(ctx context.Context, idx uint64) (
 	}
 
 	elapsed := time.Since(start)
-	log.Debugf("Completed scanning invoices added since index %v: "+
+	log.Debugf("Completed scanning for invoices added since index %v: "+
 		"total_processed=%d, found_invoices=%d, elapsed=%v",
 		idx, processedCount, len(result),
 		elapsed.Round(time.Millisecond))