From 86eb0a33839df849aa5c868d4e26962d89c3011b Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Mon, 8 Apr 2019 10:34:41 +0200 Subject: [PATCH 1/2] cnct: log go to chain reason This commit adds logging of the reason to go to chain for a channel. This can help users to find out the reason why a channels forced closed. To get all go to chain reasons, an optimization to break early is removed. This optimization was not significant, because the normal flow already examined all htlcs. In the exceptional case where we need to go to chain, it does not weigh up against logging all go to chain reasons. --- contractcourt/channel_arbitrator.go | 42 +++++++++++++++++++---------- 1 file changed, 28 insertions(+), 14 deletions(-) diff --git a/contractcourt/channel_arbitrator.go b/contractcourt/channel_arbitrator.go index 87e6221ea..80088d734 100644 --- a/contractcourt/channel_arbitrator.go +++ b/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 any of our HTLC's triggered an on-chain action, then we - // can break early. - if haveChainActions { - break + + if toChain { + log.Debugf("ChannelArbitrator(%v): go to chain for "+ + "outgoing htlc %x: timeout=%v, "+ + "blocks_until_expiry=%v, broadcast_delta=%v", + 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 From 33a1904dc9c4278f155c62df8abcc7e2b9278432 Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Mon, 8 Apr 2019 10:47:15 +0200 Subject: [PATCH 2/2] invoices: unify invoice log statements --- invoices/invoiceregistry.go | 22 +++++++++++++--------- 1 file changed, 13 insertions(+), 9 deletions(-) diff --git a/invoices/invoiceregistry.go b/invoices/invoiceregistry.go index b8e90429c..172eb075d 100644 --- a/invoices/invoiceregistry.go +++ b/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 { - return spew.Sdump(invoice) - })) + log.Debugf("Invoice(%v): added %v", paymentHash, + 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, })