Repository: lightningnetwork/lnd
Pull request #5686 (2021-09-02 13:29:06)

healthcheck: quit checking when max attempts are reached
This is something I found while investigating #5667. When the shutdown cannot complete, the `healthcheck` will be polling the check forever even after the max attempts are reached. This PR fixes it, also adds shutdown logs for assisting debug. 

orijbot: Visit https://dashboard.github.orijtech.com?back=0&pr=5686&remote=true&repo=yyforyongyu%2Flnd to see benchmark details.
yyforyongyu: > Re the "process not exiting" flake, this isn't what's actually causing it, right? Since we'd hit `Stop` and then shutdown the monitor anyway? Def a great change to stop the checks once they've already failed though!

Yeah it doesn't fix that:( Normally we wouldn't have this problem. It only occurs when the shutdown is blocked then the healthcheck would keep running in the background. 

Roasbeef: g2g, just needs a rebase (and another one maybe, depending on merge ordering) 

Patch:
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/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
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/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()


Test patch:
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")
 		})