multi: add debug logs to catch slow shutdown

chainntnfs/bitcoindnotify/bitcoind.go

@@ -132,7 +132,8 @@ func (b *BitcoindNotifier) Stop() error {
 		return nil
 	}
 
-	chainntnfs.Log.Info("bitcoind notifier shutting down")
+	chainntnfs.Log.Info("bitcoind notifier shutting down...")
+	defer chainntnfs.Log.Debug("bitcoind notifier shutdown complete")
 
 	// Shutdown the rpc client, this gracefully disconnects from bitcoind,
 	// and cleans up all related resources.

chainntnfs/btcdnotify/btcd.go

@@ -169,7 +169,8 @@ func (b *BtcdNotifier) Stop() error {
 		return nil
 	}
 
-	chainntnfs.Log.Info("btcd notifier shutting down")
+	chainntnfs.Log.Info("btcd notifier shutting down...")
+	defer chainntnfs.Log.Debug("btcd notifier shutdown complete")
 
 	// Shutdown the rpc client, this gracefully disconnects from btcd, and
 	// cleans up all related resources.

chainntnfs/mempool.go

@@ -174,6 +174,8 @@ func (m *MempoolNotifier) ProcessRelevantSpendTx(tx *btcutil.Tx) {
 // TearDown stops the notifier and cleans up resources.
 func (m *MempoolNotifier) TearDown() {
 	Log.Infof("Stopping mempool notifier")
+	defer Log.Debug("mempool notifier stopped")
+
 	close(m.quit)
 	m.wg.Wait()
 }

chainntnfs/neutrinonotify/neutrino.go

@@ -136,7 +136,8 @@ func (n *NeutrinoNotifier) Stop() error {
 		return nil
 	}
 
-	chainntnfs.Log.Info("neutrino notifier shutting down")
+	chainntnfs.Log.Info("neutrino notifier shutting down...")
+	defer chainntnfs.Log.Debug("neutrino notifier shutdown complete")
 
 	close(n.quit)
 	n.wg.Wait()

chanbackup/pubsub.go

@@ -158,7 +158,8 @@ func (s *SubSwapper) Start() error {
 // Stop signals the SubSwapper to being a graceful shutdown.
 func (s *SubSwapper) Stop() error {
 	s.stopped.Do(func() {
-		log.Infof("Stopping chanbackup.SubSwapper")
+		log.Infof("chanbackup.SubSwapper shutting down...")
+		defer log.Debug("chanbackup.SubSwapper shutdown complete")
 
 		close(s.quit)
 		s.wg.Wait()

chanfitness/chaneventstore.go

@@ -203,7 +203,8 @@ func (c *ChannelEventStore) Start() error {
 
 // Stop terminates all goroutines started by the event store.
 func (c *ChannelEventStore) Stop() {
-	log.Info("Stopping event store")
+	log.Info("ChannelEventStore shutting down...")
+	defer log.Debug("ChannelEventStore shutdown complete")
 
 	// Stop the consume goroutine.
 	close(c.quit)

channelnotifier/channelnotifier.go

@@ -104,7 +104,9 @@ func (c *ChannelNotifier) Start() error {
 func (c *ChannelNotifier) Stop() error {
 	var err error
 	c.stopped.Do(func() {
-		log.Info("ChannelNotifier shutting down")
+		log.Info("ChannelNotifier shutting down...")
+		defer log.Debug("ChannelNotifier shutdown complete")
+
 		err = c.ntfnServer.Stop()
 	})
 	return err

contractcourt/breacharbiter.go

@@ -310,7 +310,8 @@ func (b *BreachArbiter) start() error {
 // the BreachArbiter have gracefully exited.
 func (b *BreachArbiter) Stop() error {
 	b.stopped.Do(func() {
-		brarLog.Infof("Breach arbiter shutting down")
+		brarLog.Infof("Breach arbiter shutting down...")
+		defer brarLog.Debug("Breach arbiter shutdown complete")
 
 		close(b.quit)
 		b.wg.Wait()

contractcourt/chain_arbitrator.go

@@ -919,7 +919,8 @@ func (c *ChainArbitrator) Stop() error {
 		return nil
 	}
 
-	log.Info("ChainArbitrator shutting down")
+	log.Info("ChainArbitrator shutting down...")
+	defer log.Debug("ChainArbitrator shutdown complete")
 
 	close(c.quit)
 

contractcourt/utxonursery.go

@@ -319,7 +319,8 @@ func (u *UtxoNursery) Stop() error {
 		return nil
 	}
 
-	utxnLog.Infof("UTXO nursery shutting down")
+	utxnLog.Infof("UTXO nursery shutting down...")
+	defer utxnLog.Debug("UTXO nursery shutdown complete")
 
 	close(u.quit)
 	u.wg.Wait()

discovery/gossiper.go

@@ -728,7 +728,9 @@ func (d *AuthenticatedGossiper) resendFutureMessages(height uint32) {
 // Stop signals any active goroutines for a graceful closure.
 func (d *AuthenticatedGossiper) Stop() error {
 	d.stopped.Do(func() {
-		log.Info("Authenticated gossiper shutting down")
+		log.Info("Authenticated gossiper shutting down...")
+		defer log.Debug("Authenticated gossiper shutdown complete")
+
 		d.stop()
 	})
 	return nil

funding/manager.go

@@ -754,7 +754,9 @@ func (f *Manager) start() error {
 // method will block until all goroutines have exited.
 func (f *Manager) Stop() error {
 	f.stopped.Do(func() {
-		log.Info("Funding manager shutting down")
+		log.Info("Funding manager shutting down...")
+		defer log.Debug("Funding manager shutdown complete")
+
 		close(f.quit)
 		f.wg.Wait()
 	})

healthcheck/healthcheck.go

@@ -87,7 +87,8 @@ func (m *Monitor) Stop() error {
 		return fmt.Errorf("monitor already stopped")
 	}
 
-	log.Info("Health monitor shutting down")
+	log.Info("Health monitor shutting down...")
+	defer log.Debug("Health monitor shutdown complete")
 
 	close(m.quit)
 	m.wg.Wait()

htlcswitch/hop/iterator.go

@@ -139,7 +139,8 @@ func (p *OnionProcessor) Start() error {
 // Stop shutsdown the onion processor's sphinx router.
 func (p *OnionProcessor) Stop() error {
 
-	log.Info("Onion processor shutting down")
+	log.Info("Onion processor shutting down...")
+	defer log.Debug("Onion processor shutdown complete")
 
 	p.router.Stop()
 	return nil

htlcswitch/htlcnotifier.go

@@ -92,7 +92,9 @@ func (h *HtlcNotifier) Start() error {
 func (h *HtlcNotifier) Stop() error {
 	var err error
 	h.stopped.Do(func() {
-		log.Info("HtlcNotifier shutting down")
+		log.Info("HtlcNotifier shutting down...")
+		defer log.Debug("HtlcNotifier shutdown complete")
+
 		if err = h.ntfnServer.Stop(); err != nil {
 			log.Warnf("error stopping htlc notifier: %v", err)
 		}

htlcswitch/switch.go

@@ -2244,7 +2244,8 @@ func (s *Switch) Stop() error {
 		return errors.New("htlc switch already shutdown")
 	}
 
-	log.Info("HTLC Switch shutting down")
+	log.Info("HTLC Switch shutting down...")
+	defer log.Debug("HTLC Switch shutdown complete")
 
 	close(s.quit)
 

invoices/invoiceregistry.go

@@ -275,7 +275,8 @@ func (i *InvoiceRegistry) Start() error {
 
 // Stop signals the registry for a graceful shutdown.
 func (i *InvoiceRegistry) Stop() error {
-	log.Info("InvoiceRegistry shutting down")
+	log.Info("InvoiceRegistry shutting down...")
+	defer log.Debug("InvoiceRegistry shutdown complete")
 
 	i.expiryWatcher.Stop()
 

netann/chan_status_manager.go

@@ -225,7 +225,9 @@ 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")
+		log.Info("Channel Status Manager shutting down...")
+		defer log.Debug("Channel Status Manager shutdown complete")
+
 		close(m.quit)
 		m.wg.Wait()
 	})

netann/host_ann.go

@@ -69,7 +69,9 @@ 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")
+		log.Info("HostAnnouncer shutting down...")
+		defer log.Debug("HostAnnouncer shutdown complete")
+
 		close(h.quit)
 		h.wg.Wait()
 	})

peernotifier/peernotifier.go

@@ -52,7 +52,9 @@ func (p *PeerNotifier) Start() error {
 func (p *PeerNotifier) Stop() error {
 	var err error
 	p.stopped.Do(func() {
-		log.Info("PeerNotifier shutting down")
+		log.Info("PeerNotifier shutting down...")
+		defer log.Debug("PeerNotifier shutdown complete")
+
 		err = p.ntfnServer.Stop()
 	})
 	return err

routing/missioncontrol.go

@@ -240,6 +240,9 @@ func (m *MissionControl) RunStoreTicker() {
 
 // StopStoreTicker stops the mission control store's ticker.
 func (m *MissionControl) StopStoreTicker() {
+	log.Debug("Stopping mission control store ticker")
+	defer log.Debug("Mission control store ticker stopped")
+
 	m.store.stop()
 }
 

routing/router.go

@@ -699,7 +699,8 @@ func (r *ChannelRouter) Stop() error {
 		return nil
 	}
 
-	log.Info("Channel Router shutting down")
+	log.Info("Channel Router shutting down...")
+	defer log.Debug("Channel Router shutdown complete")
 
 	// Our filtered chain view could've only been started if
 	// AssumeChannelValid isn't present.

server.go

@@ -2328,8 +2328,10 @@ func (s *server) Stop() error {
 		}
 
 		// Wait for all lingering goroutines to quit.
+		srvrLog.Debug("Waiting for server to shutdown...")
 		s.wg.Wait()
 
+		srvrLog.Debug("Stopping buffer pools...")
 		s.sigPool.Stop()
 		s.writePool.Stop()
 		s.readPool.Stop()
@@ -3957,6 +3959,9 @@ func (s *server) peerInitializer(p *peer.Brontide) {
 	// Start the peer! If an error occurs, we Disconnect the peer, which
 	// will unblock the peerTerminationWatcher.
 	if err := p.Start(); err != nil {
+		srvrLog.Warnf("Starting peer=%v got error: %v",
+			p.IdentityKey(), err)
+
 		p.Disconnect(fmt.Errorf("unable to start peer: %v", err))
 		return
 	}

sweep/sweeper.go

@@ -409,13 +409,12 @@ func (s *UtxoSweeper) Stop() error {
 		return nil
 	}
 
-	log.Info("Sweeper shutting down")
+	log.Info("Sweeper shutting down...")
+	defer log.Debug("Sweeper shutdown complete")
 
 	close(s.quit)
 	s.wg.Wait()
 
-	log.Debugf("Sweeper shut down")
-
 	return nil
 }