From 3204e2d74b8c677e75e84cd6b8b65e9f0a49c7bf Mon Sep 17 00:00:00 2001 From: yyforyongyu Date: Thu, 2 Sep 2021 20:26:00 +0800 Subject: [PATCH 1/3] multi: add shutdown logs in subservers This commit adds a simple shutdown to every subserver to assist debugging. --- chainntnfs/bitcoindnotify/bitcoind.go | 2 ++ chainntnfs/btcdnotify/btcd.go | 2 ++ chainntnfs/neutrinonotify/neutrino.go | 2 ++ channelnotifier/channelnotifier.go | 1 + contractcourt/chain_arbitrator.go | 2 +- discovery/gossiper.go | 5 ++++- htlcswitch/hop/iterator.go | 3 +++ htlcswitch/htlcnotifier.go | 1 + htlcswitch/switch.go | 2 +- invoices/invoiceregistry.go | 2 ++ netann/chan_status_manager.go | 1 + netann/host_ann.go | 1 + peernotifier/peernotifier.go | 2 +- routing/router.go | 2 +- sweep/sweeper.go | 2 +- 15 files changed, 24 insertions(+), 6 deletions(-) diff --git a/chainntnfs/bitcoindnotify/bitcoind.go b/chainntnfs/bitcoindnotify/bitcoind.go index 3dce1ae83..d4206d310 100644 --- a/chainntnfs/bitcoindnotify/bitcoind.go +++ b/chainntnfs/bitcoindnotify/bitcoind.go @@ -118,6 +118,8 @@ func (b *BitcoindNotifier) Stop() error { return nil } + chainntnfs.Log.Info("bitcoind notifier shutting down") + // Shutdown the rpc client, this gracefully disconnects from bitcoind, // and cleans up all related resources. b.chainConn.Stop() diff --git a/chainntnfs/btcdnotify/btcd.go b/chainntnfs/btcdnotify/btcd.go index 6a84df7d5..9ddcbb93c 100644 --- a/chainntnfs/btcdnotify/btcd.go +++ b/chainntnfs/btcdnotify/btcd.go @@ -161,6 +161,8 @@ func (b *BtcdNotifier) Stop() error { return nil } + chainntnfs.Log.Info("btcd notifier shutting down") + // Shutdown the rpc client, this gracefully disconnects from btcd, and // cleans up all related resources. b.chainConn.Shutdown() diff --git a/chainntnfs/neutrinonotify/neutrino.go b/chainntnfs/neutrinonotify/neutrino.go index fbe03c64b..8f7d702a8 100644 --- a/chainntnfs/neutrinonotify/neutrino.go +++ b/chainntnfs/neutrinonotify/neutrino.go @@ -136,6 +136,8 @@ func (n *NeutrinoNotifier) Stop() error { return nil } + chainntnfs.Log.Info("neutrino notifier shutting down") + close(n.quit) n.wg.Wait() diff --git a/channelnotifier/channelnotifier.go b/channelnotifier/channelnotifier.go index b99d18d40..74c2b15eb 100644 --- a/channelnotifier/channelnotifier.go +++ b/channelnotifier/channelnotifier.go @@ -97,6 +97,7 @@ func (c *ChannelNotifier) Start() error { func (c *ChannelNotifier) Stop() error { var err error c.stopped.Do(func() { + log.Info("ChannelNotifier shutting down") err = c.ntfnServer.Stop() }) return err diff --git a/contractcourt/chain_arbitrator.go b/contractcourt/chain_arbitrator.go index 2ddc9c8cd..426382dd3 100644 --- a/contractcourt/chain_arbitrator.go +++ b/contractcourt/chain_arbitrator.go @@ -893,7 +893,7 @@ func (c *ChainArbitrator) Stop() error { return nil } - log.Infof("Stopping ChainArbitrator") + log.Info("ChainArbitrator shutting down") close(c.quit) diff --git a/discovery/gossiper.go b/discovery/gossiper.go index d7f2fd5fc..e4d2d7395 100644 --- a/discovery/gossiper.go +++ b/discovery/gossiper.go @@ -467,7 +467,10 @@ func (d *AuthenticatedGossiper) start() error { // Stop signals any active goroutines for a graceful closure. func (d *AuthenticatedGossiper) Stop() error { - d.stopped.Do(d.stop) + d.stopped.Do(func() { + log.Info("Authenticated gossiper shutting down") + d.stop() + }) return nil } diff --git a/htlcswitch/hop/iterator.go b/htlcswitch/hop/iterator.go index 00929334b..20963bd7b 100644 --- a/htlcswitch/hop/iterator.go +++ b/htlcswitch/hop/iterator.go @@ -137,6 +137,9 @@ func (p *OnionProcessor) Start() error { // Stop shutsdown the onion processor's sphinx router. func (p *OnionProcessor) Stop() error { + + log.Info("Onion processor shutting down") + p.router.Stop() return nil } diff --git a/htlcswitch/htlcnotifier.go b/htlcswitch/htlcnotifier.go index 4c15c2a68..fd067e2b4 100644 --- a/htlcswitch/htlcnotifier.go +++ b/htlcswitch/htlcnotifier.go @@ -91,6 +91,7 @@ func (h *HtlcNotifier) Start() error { func (h *HtlcNotifier) Stop() error { var err error h.stopped.Do(func() { + log.Info("HtlcNotifier shutting down") if err = h.ntfnServer.Stop(); err != nil { log.Warnf("error stopping htlc notifier: %v", err) } diff --git a/htlcswitch/switch.go b/htlcswitch/switch.go index a9874c425..676eab8e8 100644 --- a/htlcswitch/switch.go +++ b/htlcswitch/switch.go @@ -1942,7 +1942,7 @@ func (s *Switch) Stop() error { return errors.New("htlc switch already shutdown") } - log.Infof("HTLC Switch shutting down") + log.Info("HTLC Switch shutting down") close(s.quit) diff --git a/invoices/invoiceregistry.go b/invoices/invoiceregistry.go index 7bb9a4df4..1e705c651 100644 --- a/invoices/invoiceregistry.go +++ b/invoices/invoiceregistry.go @@ -257,6 +257,8 @@ func (i *InvoiceRegistry) Start() error { // Stop signals the registry for a graceful shutdown. func (i *InvoiceRegistry) Stop() error { + log.Info("InvoiceRegistry shutting down") + i.expiryWatcher.Stop() close(i.quit) diff --git a/netann/chan_status_manager.go b/netann/chan_status_manager.go index b0188625b..212bd4dae 100644 --- a/netann/chan_status_manager.go +++ b/netann/chan_status_manager.go @@ -217,6 +217,7 @@ func (m *ChanStatusManager) start() error { // Stop safely shuts down the ChanStatusManager. func (m *ChanStatusManager) Stop() error { m.stopped.Do(func() { + log.Info("Channel Status Manager shutting down") close(m.quit) m.wg.Wait() }) diff --git a/netann/host_ann.go b/netann/host_ann.go index 48189cfeb..3e87c4b0f 100644 --- a/netann/host_ann.go +++ b/netann/host_ann.go @@ -68,6 +68,7 @@ func (h *HostAnnouncer) Start() error { // Stop signals the HostAnnouncer for a graceful stop. func (h *HostAnnouncer) Stop() error { h.stopOnce.Do(func() { + log.Info("HostAnnouncer shutting down") close(h.quit) h.wg.Wait() }) diff --git a/peernotifier/peernotifier.go b/peernotifier/peernotifier.go index 4a92ff262..d24c2cf92 100644 --- a/peernotifier/peernotifier.go +++ b/peernotifier/peernotifier.go @@ -52,7 +52,7 @@ func (p *PeerNotifier) Start() error { func (p *PeerNotifier) Stop() error { var err error p.stopped.Do(func() { - log.Info("Stopping PeerNotifier") + log.Info("PeerNotifier shutting down") err = p.ntfnServer.Stop() }) return err diff --git a/routing/router.go b/routing/router.go index 8b9cd97da..6ebf86c19 100644 --- a/routing/router.go +++ b/routing/router.go @@ -691,7 +691,7 @@ func (r *ChannelRouter) Stop() error { return nil } - log.Tracef("Channel Router shutting down") + log.Info("Channel Router shutting down") // Our filtered chain view could've only been started if // AssumeChannelValid isn't present. diff --git a/sweep/sweeper.go b/sweep/sweeper.go index 5869e4564..f1f93aa6c 100644 --- a/sweep/sweeper.go +++ b/sweep/sweeper.go @@ -427,7 +427,7 @@ func (s *UtxoSweeper) Stop() error { return nil } - log.Debugf("Sweeper shutting down") + log.Info("Sweeper shutting down") close(s.quit) s.wg.Wait() From d19ee28089ef8ae497ede706bef49dc921055fa1 Mon Sep 17 00:00:00 2001 From: yyforyongyu Date: Thu, 2 Sep 2021 21:13:23 +0800 Subject: [PATCH 2/3] healthcheck: stop checking when max attempts are reached This commit adds a check to the returned error from calling retryCheck such that when the max number of attempts is reached, the health check will quit. --- healthcheck/healthcheck.go | 32 ++++++++++---- healthcheck/healthcheck_test.go | 77 ++++++++++++++++++++------------- 2 files changed, 70 insertions(+), 39 deletions(-) diff --git a/healthcheck/healthcheck.go b/healthcheck/healthcheck.go index 8f92d9aac..5244eb888 100644 --- a/healthcheck/healthcheck.go +++ b/healthcheck/healthcheck.go @@ -86,6 +86,8 @@ func (m *Monitor) Stop() error { return fmt.Errorf("monitor already stopped") } + log.Info("Health monitor shutting down") + close(m.quit) m.wg.Wait() @@ -166,10 +168,18 @@ func (o *Observation) monitor(shutdown shutdownFunc, quit chan struct{}) { for { select { case <-o.Interval.Ticks(): - o.retryCheck(quit, shutdown) + // retryCheck will return errMaxAttemptsReached when + // the max attempts are reached. In that case we will + // stop the ticker and quit. + if o.retryCheck(quit, shutdown) { + log.Debugf("Health check: max attempts " + + "failed, monitor exiting") + return + } // Exit if we receive the instruction to shutdown. case <-quit: + log.Debug("Health check: monitor quit") return } } @@ -178,8 +188,11 @@ func (o *Observation) monitor(shutdown shutdownFunc, quit chan struct{}) { // retryCheck calls a check function until it succeeds, or we reach our // configured number of attempts, waiting for our back off period between failed // calls. If we fail to obtain a passing health check after the allowed number -// of calls, we will request shutdown. -func (o *Observation) retryCheck(quit chan struct{}, shutdown shutdownFunc) { +// of calls, we will request shutdown. It returns a bool to indicate whether +// the max number of attempts is reached. +func (o *Observation) retryCheck(quit chan struct{}, + shutdown shutdownFunc) bool { + var count int for count < o.Attempts { @@ -197,13 +210,14 @@ func (o *Observation) retryCheck(quit chan struct{}, shutdown shutdownFunc) { "%v", o, o.Timeout) case <-quit: - return + log.Debug("Health check: monitor quit") + return false } // If our error is nil, we have passed our health check, so we // can exit. if err == nil { - return + return false } // If we have reached our allowed number of attempts, this @@ -211,8 +225,7 @@ func (o *Observation) retryCheck(quit chan struct{}, shutdown shutdownFunc) { if count == o.Attempts { shutdown("Health check: %v failed after %v "+ "calls", o, o.Attempts) - - return + return true } log.Infof("Health check: %v, call: %v failed with: %v, "+ @@ -225,7 +238,10 @@ func (o *Observation) retryCheck(quit chan struct{}, shutdown shutdownFunc) { case <-time.After(o.Backoff): case <-quit: - return + log.Debug("Health check: monitor quit") + return false } } + + return false } diff --git a/healthcheck/healthcheck_test.go b/healthcheck/healthcheck_test.go index ed810ed73..b198e60a5 100644 --- a/healthcheck/healthcheck_test.go +++ b/healthcheck/healthcheck_test.go @@ -132,48 +132,58 @@ func TestRetryCheck(t *testing.T) { // expectedShutdown is true if we expect a shutdown to be // triggered because all of our calls failed. expectedShutdown bool + + // maxAttemptsReached specifies whether the max allowed + // attempts are reached from calling retryCheck. + maxAttemptsReached bool }{ { - name: "first call succeeds", - errors: []error{nil}, - attempts: 2, - timeout: time.Hour, - expectedShutdown: false, + name: "first call succeeds", + errors: []error{nil}, + attempts: 2, + timeout: time.Hour, + expectedShutdown: false, + maxAttemptsReached: false, }, { - name: "first call fails", - errors: []error{errNonNil}, - attempts: 1, - timeout: time.Hour, - expectedShutdown: true, + name: "first call fails", + errors: []error{errNonNil}, + attempts: 1, + timeout: time.Hour, + expectedShutdown: true, + maxAttemptsReached: true, }, { - name: "fail then recover", - errors: []error{errNonNil, nil}, - attempts: 2, - timeout: time.Hour, - expectedShutdown: false, + name: "fail then recover", + errors: []error{errNonNil, nil}, + attempts: 2, + timeout: time.Hour, + expectedShutdown: false, + maxAttemptsReached: false, }, { - name: "always fail", - errors: []error{errNonNil, errNonNil}, - attempts: 2, - timeout: time.Hour, - expectedShutdown: true, + name: "always fail", + errors: []error{errNonNil, errNonNil}, + attempts: 2, + timeout: time.Hour, + expectedShutdown: true, + maxAttemptsReached: true, }, { - name: "no calls", - errors: nil, - attempts: 0, - timeout: time.Hour, - expectedShutdown: false, + name: "no calls", + errors: nil, + attempts: 0, + timeout: time.Hour, + expectedShutdown: false, + maxAttemptsReached: false, }, { - name: "call times out", - errors: nil, - attempts: 1, - timeout: 1, - expectedShutdown: true, + name: "call times out", + errors: nil, + attempts: 1, + timeout: 1, + expectedShutdown: true, + maxAttemptsReached: true, }, } @@ -203,8 +213,11 @@ func TestRetryCheck(t *testing.T) { // on us sending errors into the mocked caller's error // channel. done := make(chan struct{}) + retryResult := false go func() { - observation.retryCheck(quit, shutdownFunc) + retryResult = observation.retryCheck( + quit, shutdownFunc, + ) close(done) }() @@ -218,6 +231,8 @@ func TestRetryCheck(t *testing.T) { // check function before we start checking results. <-done + require.Equal(t, test.maxAttemptsReached, retryResult, + "retryCheck returned unexpected error") require.Equal(t, test.expectedShutdown, shutdown, "unexpected shutdown state") }) From 3b4965d7768680fb96bf009ccd556d3443d8f715 Mon Sep 17 00:00:00 2001 From: yyforyongyu Date: Thu, 2 Sep 2021 21:18:58 +0800 Subject: [PATCH 3/3] docs: update release note for healthcheck fix --- docs/release-notes/release-notes-0.14.0.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/docs/release-notes/release-notes-0.14.0.md b/docs/release-notes/release-notes-0.14.0.md index 14a1da06b..a2e865658 100644 --- a/docs/release-notes/release-notes-0.14.0.md +++ b/docs/release-notes/release-notes-0.14.0.md @@ -292,6 +292,8 @@ mode](https://github.com/lightningnetwork/lnd/pull/5564). [Catches up on blocks in the router](https://github.com/lightningnetwork/lnd/pull/5315) in order to fix an "out of order" error that crops up. +[Fix healthcheck might be running after the max number of attempts are reached.](https://github.com/lightningnetwork/lnd/pull/5686) + ## Documentation The [code contribution guidelines have been updated to mention the new