Merge pull request #2908 from joostjager/chan-arb-logging

cnct+invoices: improve logging

contractcourt/channel_arbitrator.go

@@ -1097,26 +1097,27 @@ func (c *ChannelArbitrator) checkChainActions(height uint32,
 	// outgoing HTLC's to decide if we need to go on chain at all.
 	haveChainActions := false
 	for _, htlc := range c.activeHTLCs.outgoingHTLCs {
-		// If any of our HTLC's triggered an on-chain action, then we
-		// can break early.
-		if haveChainActions {
-			break
-		}
-
 		// We'll need to go on-chain for an outgoing HTLC if it was
 		// never resolved downstream, and it's "close" to timing out.
-		haveChainActions = haveChainActions || c.shouldGoOnChain(
+		toChain := c.shouldGoOnChain(
 			htlc.RefundTimeout, c.cfg.OutgoingBroadcastDelta,
 			height,
 		)
-	}
+
-	for _, htlc := range c.activeHTLCs.incomingHTLCs {
+		if toChain {
-		// If any of our HTLC's triggered an on-chain action, then we
+			log.Debugf("ChannelArbitrator(%v): go to chain for "+
-		// can break early.
+				"outgoing htlc %x: timeout=%v, "+
-		if haveChainActions {
+				"blocks_until_expiry=%v, broadcast_delta=%v",
-			break
+				c.cfg.ChanPoint, htlc.RHash[:],
+				htlc.RefundTimeout, htlc.RefundTimeout-height,
+				c.cfg.OutgoingBroadcastDelta,
+			)
 		}
 
+		haveChainActions = haveChainActions || toChain
+	}
+
+	for _, htlc := range c.activeHTLCs.incomingHTLCs {
 		// We'll need to go on-chain to pull an incoming HTLC iff we
 		// know the pre-image and it's close to timing out. We need to
 		// ensure that we claim the funds that our rightfully ours
@@ -1124,10 +1125,23 @@ func (c *ChannelArbitrator) checkChainActions(height uint32,
 		if _, ok := c.cfg.PreimageDB.LookupPreimage(htlc.RHash); !ok {
 			continue
 		}
-		haveChainActions = haveChainActions || c.shouldGoOnChain(
+
+		toChain := c.shouldGoOnChain(
 			htlc.RefundTimeout, c.cfg.IncomingBroadcastDelta,
 			height,
 		)
+
+		if toChain {
+			log.Debugf("ChannelArbitrator(%v): go to chain for "+
+				"incoming htlc %x: timeout=%v, "+
+				"blocks_until_expiry=%v, broadcast_delta=%v",
+				c.cfg.ChanPoint, htlc.RHash[:],
+				htlc.RefundTimeout, htlc.RefundTimeout-height,
+				c.cfg.IncomingBroadcastDelta,
+			)
+		}
+
+		haveChainActions = haveChainActions || toChain
 	}
 
 	// If we don't have any actions to make, then we'll return an empty

invoices/invoiceregistry.go

@@ -408,9 +408,11 @@ func (i *InvoiceRegistry) AddInvoice(invoice *channeldb.Invoice,
 	i.Lock()
 	defer i.Unlock()
 
-	log.Debugf("Adding invoice %v", newLogClosure(func() string {
+	log.Debugf("Invoice(%v): added %v", paymentHash,
-		return spew.Sdump(invoice)
+		newLogClosure(func() string {
-	}))
+			return spew.Sdump(invoice)
+		}),
+	)
 
 	addIndex, err := i.cdb.AddInvoice(invoice, paymentHash)
 	if err != nil {
@@ -476,7 +478,7 @@ func (i *InvoiceRegistry) NotifyExitHopHtlc(rHash lntypes.Hash,
 	i.Lock()
 	defer i.Unlock()
 
-	log.Debugf("Settling invoice %x", rHash[:])
+	log.Debugf("Invoice(%x): htlc accepted", rHash[:])
 
 	createEvent := func(preimage *lntypes.Preimage) *HodlEvent {
 		return &HodlEvent{
@@ -519,6 +521,8 @@ func (i *InvoiceRegistry) NotifyExitHopHtlc(rHash lntypes.Hash,
 		i.notifyClients(rHash, invoice, invoice.Terms.State)
 		switch invoice.Terms.State {
 		case channeldb.ContractSettled:
+			log.Debugf("Invoice(%x): settled", rHash[:])
+
 			return createEvent(&invoice.Terms.PaymentPreimage), nil
 		case channeldb.ContractAccepted:
 			// Subscribe to updates to this invoice.
@@ -541,12 +545,12 @@ func (i *InvoiceRegistry) SettleHodlInvoice(preimage lntypes.Preimage) error {
 
 	invoice, err := i.cdb.SettleHoldInvoice(preimage)
 	if err != nil {
-		log.Errorf("Invoice SetPreimage %v: %v", preimage, err)
+		log.Errorf("SettleHodlInvoice with preimage %v: %v", preimage, err)
 		return err
 	}
 
 	hash := preimage.Hash()
-	log.Infof("Notifying clients of set preimage to %v",
+	log.Debugf("Invoice(%v): settled with preimage %v", hash,
 		invoice.Terms.PaymentPreimage)
 
 	i.notifyHodlSubscribers(HodlEvent{
@@ -564,21 +568,21 @@ func (i *InvoiceRegistry) CancelInvoice(payHash lntypes.Hash) error {
 	i.Lock()
 	defer i.Unlock()
 
-	log.Debugf("Canceling invoice %v", payHash)
+	log.Debugf("Invoice(%v): canceling invoice", payHash)
 
 	invoice, err := i.cdb.CancelInvoice(payHash)
 
 	// Implement idempotency by returning success if the invoice was already
 	// canceled.
 	if err == channeldb.ErrInvoiceAlreadyCanceled {
-		log.Debugf("Invoice %v already canceled", payHash)
+		log.Debugf("Invoice(%v): already canceled", payHash)
 		return nil
 	}
 	if err != nil {
 		return err
 	}
 
-	log.Infof("Invoice %v canceled", payHash)
+	log.Debugf("Invoice(%v): canceled", payHash)
 	i.notifyHodlSubscribers(HodlEvent{
 		Hash: payHash,
 	})