Throttle "waiting for x to stop" messages. Fixes #560

supervisor/process.py

@@ -39,6 +39,7 @@ class Subprocess:
     event = None # event currently being processed (if we're an event listener)
     laststart = 0 # Last time the subprocess was started; 0 if never
     laststop = 0  # Last time the subprocess was stopped; 0 if never
+    laststopreport = 0 # Last time "waiting for x to stop" logged, to throttle
     delay = 0 # If nonzero, delay starting or killing until this time
     administrative_stop = 0 # true if the process has been stopped by an admin
     system_stop = 0 # true if the process has been stopped by the system
@@ -350,8 +351,18 @@ class Subprocess:
     def stop(self):
         """ Administrative stop """
         self.administrative_stop = 1
+        self.laststopreport = 0
         return self.kill(self.config.stopsignal)
 
+    def stop_report(self):
+        """ Log a 'waiting for x to stop' message with throttling. """
+        if self.state == ProcessStates.STOPPING:
+            now = time.time()
+            if now > (self.laststopreport + 2): # every 2 seconds
+                self.config.options.logger.info(
+                    'waiting for %s to stop' % self.config.name)
+                self.laststopreport = now
+
     def give_up(self):
         self.delay = 0
         self.backoff = 0

supervisor/rpcinterface.py

@@ -405,9 +405,7 @@ class SupervisorNamespaceRPCInterface:
                 # process will eventually enter a stopped state by
                 # virtue of the supervisord.reap() method being called
                 # during normal operations
-                self.supervisord.options.logger.info(
-                    'waiting for %s to stop' % process.config.name
-                    )
+                process.stop_report()
                 if process.get_state() not in STOPPED_STATES:
                     return NOT_DONE_YET
                 return True

supervisor/tests/base.py

@@ -380,6 +380,7 @@ class DummyProcess:
         self.config = config
         self.logsremoved = False
         self.stop_called = False
+        self.stop_report_called = True
         self.backoff_secs = None
         self.spawned = False
         if state is None:
@@ -422,6 +423,9 @@ class DummyProcess:
         from supervisor.process import ProcessStates
         self.state = ProcessStates.STOPPED
 
+    def stop_report(self):
+        self.stop_report_called = True
+
     def kill(self, signal):
         self.killed_with = signal
 

supervisor/tests/test_process.py

@@ -683,8 +683,10 @@ class SubprocessTests(unittest.TestCase):
         instance.dispatchers = {'foo':dispatcher}
         from supervisor.states import ProcessStates
         instance.state = ProcessStates.RUNNING
+        instance.laststopreport = time.time()
         instance.stop()
         self.assertEqual(instance.administrative_stop, 1)
+        self.assertEqual(instance.laststopreport, 0)
         self.assertTrue(instance.delay)
         self.assertEqual(options.logger.data[0], 'killing test (pid 11) with '
                          'signal SIGTERM')
@@ -707,6 +709,35 @@ class SubprocessTests(unittest.TestCase):
             self.assertEqual(exc.args[0], 'Assertion failed for test: '
                 'STOPPED not in RUNNING STARTING STOPPING')
 
+    def test_stop_report_logs_nothing_if_not_stopping_state(self):
+        options = DummyOptions()
+        config = DummyPConfig(options, 'test', '/test')
+        instance = self._makeOne(config)
+        instance.pid = 11
+        dispatcher = DummyDispatcher(writable=True)
+        instance.dispatchers = {'foo':dispatcher}
+        from supervisor.states import ProcessStates
+        instance.state = ProcessStates.STOPPED
+        instance.stop_report()
+        self.assertEqual(len(options.logger.data), 0)
+
+    def test_stop_report_logs_throttled_by_laststopreport(self):
+        options = DummyOptions()
+        config = DummyPConfig(options, 'test', '/test')
+        instance = self._makeOne(config)
+        instance.pid = 11
+        dispatcher = DummyDispatcher(writable=True)
+        instance.dispatchers = {'foo':dispatcher}
+        from supervisor.states import ProcessStates
+        instance.state = ProcessStates.STOPPING
+        self.assertEqual(instance.laststopreport, 0)
+        instance.stop_report()
+        self.assertEqual(len(options.logger.data), 1)
+        self.assertEqual(options.logger.data[0], 'waiting for test to stop')
+        self.assertNotEqual(instance.laststopreport, 0)
+        instance.stop_report()
+        self.assertEqual(len(options.logger.data), 1) # throttled
+
     def test_give_up(self):
         options = DummyOptions()
         config = DummyPConfig(options, 'test', '/test')

supervisor/tests/test_rpcinterfaces.py

@@ -612,7 +612,6 @@ class SupervisorNamespaceXMLRPCInterfaceTests(TestBase):
              ]
             )
 
-
     def test_stopProcess(self):
         options = DummyOptions()
         pconfig = DummyPConfig(options, 'foo', '/bin/foo')
@@ -628,6 +627,7 @@ class SupervisorNamespaceXMLRPCInterfaceTests(TestBase):
         self.assertEqual(process.delay, 0)
         self.assertEqual(process.killing, 0)
         self.assertEqual(process.state, ProcessStates.STOPPED)
+        self.assertTrue(process.stop_report_called)
         self.assertEqual(len(supervisord.process_groups['foo'].processes), 1)
         self.assertEqual(interface.update_text, 'stopProcess')
 
@@ -642,6 +642,7 @@ class SupervisorNamespaceXMLRPCInterfaceTests(TestBase):
         self.assertEqual(result, True)
         process = supervisord.process_groups['foo'].processes['foo']
         self.assertEqual(process.stop_called, True)
+        self.assertTrue(process.stop_report_called)
         self.assertEqual(interface.update_text, 'stopProcess')
 
     def test_stopProcess_success_in_onwait(self):