Fix AssertionError if subprocess exits after system time is set back.

Fixes Supervisor#281 Fixes Supervisor#458 Fixes Supervisor#533 Fixes Supervisor#552 Fixes Supervisor#618
weka-io · Dec 24, 2015 · 423cfc5 · 423cfc5
1 parent d46e346
commit 423cfc5
Show file tree

Hide file tree

Showing 3 changed files with 159 additions and 20 deletions.
diff --git a/CHANGES.txt b/CHANGES.txt
@@ -1,3 +1,59 @@
+
+- ``supervisorctl start`` and ``supervisorctl stop`` now complete more quickly
+  when handling many processes.  Thanks to Chris McDonough for this patch.
+  See: https://github.com/Supervisor/supervisor/issues/131
+
+- Environment variables are now expanded for all config file options.
+  Patch by Dexter Tad-y.
+
+- Errors caused by bad values in a config file now show the config section
+  to make debugging easier.  Patch by Marc Abramowitz.
+
+- Setting ``redirect_stderr=true`` in an `[eventlistener:x]`` section is now
+  disallowed because any messages written to ``stderr`` would interfere
+  with the eventlistener protocol on ``stdout``.
+
+- Fixed a bug where spawning a process could cause ``supervisord`` to crash
+  if an ``IOError`` occurred while setting up logging.  One way this could
+  happen is if a log filename was accidentally set to a directory instead
+  of a file.  Thanks to Grzegorz Nosek for reporting this issue.
+
+- Fixed a bug introduced in 3.1.0 where ``supervisord`` could crash when
+  attempting to display a resource limit error.
+
+- Fixed a bug where ``supervisord`` could crash with the message
+  ``Assertion failed for processname: RUNNING not in STARTING`` if a time
+  change caused the last start time of the process to be in the future.
+  Thanks to Róbert Nagy, Sergey Leschenko, and samhair for the patches.
+
+- Errors from the web interface are now logged at the ``ERROR`` level.
+  Previously, they were logged at the ``TRACE`` level and easily
+  missed.  Thanks to Thomas Güttler for reporting this issue.
+
+- Fixed ``DeprecationWarning: Parameters to load are deprecated. Call
+  .resolve and .require separately.`` on setuptools >= 11.3.
+
+3.1.3 (2014-10-28)
+------------------
+
+- Fixed an XML-RPC bug where the ElementTree-based parser handled strings
+  like ``<value><string>hello</string></value>`` but not strings like
+  ``<value>hello</value>``, which are valid in the XML-RPC spec.  This
+  fixes compatibility with the Apache XML-RPC client for Java and
+  possibly other clients.
+
+3.1.2 (2014-09-07)
+------------------
+
+- Fixed a bug where ``tail group:*`` in ``supervisorctl`` would show a 500
+  Internal Server Error rather than a BAD_NAME fault.
+
+- Fixed a bug where the web interface would show a 500 Internal Server Error
+  instead of an error message for some process start faults.
+
+- Removed medusa files not used by Supervisor.
+
+>>>>>>> eb96a2a... Fix AssertionError if subprocess exits after system time is set back.
 3.1.1 (2014-08-11)
 ------------------
 

diff --git a/supervisor/process.py b/supervisor/process.py
@@ -441,7 +441,15 @@ def finish(self, pid, sts):
         self.laststop = now
         processname = self.config.name
 
-        tooquickly = now - self.laststart < self.config.startsecs
+        if now > self.laststart:
+            too_quickly = now - self.laststart < self.config.startsecs
+        else:
+            too_quickly = False
+            self.config.options.logger.warn(
+                "process %r (%s) laststart time is in the future, don't "
+                "know how long process was running so assuming it did "
+                "not exit too quickly" % (self.config.name, self.pid))
+
         exit_expected = es in self.config.exitcodes
 
         if self.killing:
@@ -455,7 +463,7 @@ def finish(self, pid, sts):
             self._assertInState(ProcessStates.STOPPING)
             self.change_state(ProcessStates.STOPPED)
 
-        elif tooquickly:
+        elif too_quickly:
             # the program did not stay up long enough to make it to RUNNING
             # implies STARTING -> BACKOFF
             self.exitstatus = None
@@ -466,18 +474,16 @@ def finish(self, pid, sts):
 
         else:
             # this finish was not the result of a stop request, the
-            # program was in the RUNNING state but exited implies
-            # RUNNING -> EXITED
+            # program was in the RUNNING state but exited
+            # implies RUNNING -> EXITED normally but see next comment
             self.delay = 0
             self.backoff = 0
             self.exitstatus = es
 
-            if self.state == ProcessStates.STARTING: # pragma: no cover
-                # XXX I don't know under which circumstances this
-                # happens, but in the wild, there is a transition that
-                # subverts the RUNNING state (directly from STARTING
-                # to EXITED), so we perform the correct transition
-                # here.
+            # if the process was STARTING but a system time change causes
+            # self.laststart to be in the future, the normal STARTING->RUNNING
+            # transition can be subverted so we perform the transition here.
+            if self.state == ProcessStates.STARTING:
                 self.change_state(ProcessStates.RUNNING)
 
             self._assertInState(ProcessStates.RUNNING)

diff --git a/supervisor/tests/test_process.py b/supervisor/tests/test_process.py
@@ -804,24 +804,24 @@ def test_stopasgroup(self):
         self.assertEqual(event.extra_values, [('pid', 11)])
         self.assertEqual(event.from_state, ProcessStates.RUNNING)
 
-    def test_finish(self):
+    def test_finish_stopping_state(self):
         options = DummyOptions()
         config = DummyPConfig(options, 'notthere', '/notthere',
                               stdout_logfile='/tmp/foo')
         instance = self._makeOne(config)
         instance.waitstatus = (123, 1) # pid, waitstatus
         instance.config.options.pidhistory[123] = instance
-        instance.killing = 1
+        instance.killing = True
         pipes = {'stdout':'','stderr':''}
         instance.pipes = pipes
         from supervisor.states import ProcessStates
         from supervisor import events
         instance.state = ProcessStates.STOPPING
         L = []
-        events.subscribe(events.ProcessStateStoppedEvent, lambda x: L.append(x))
+        events.subscribe(events.ProcessStateEvent, lambda x: L.append(x))
         instance.pid = 123
         instance.finish(123, 1)
-        self.assertEqual(instance.killing, 0)
+        self.assertFalse(instance.killing)
         self.assertEqual(instance.pid, 0)
         self.assertEqual(options.parent_pipes_closed, pipes)
         self.assertEqual(instance.pipes, {})
@@ -835,7 +835,7 @@ def test_finish(self):
         self.assertEqual(event.extra_values, [('pid', 123)])
         self.assertEqual(event.from_state, ProcessStates.STOPPING)
 
-    def test_finish_expected(self):
+    def test_finish_running_state_exit_expected(self):
         options = DummyOptions()
         config = DummyPConfig(options, 'notthere', '/notthere',
                               stdout_logfile='/tmp/foo')
@@ -848,10 +848,10 @@ def test_finish_expected(self):
         from supervisor import events
         instance.state = ProcessStates.RUNNING
         L = []
-        events.subscribe(events.ProcessStateExitedEvent, lambda x: L.append(x))
+        events.subscribe(events.ProcessStateEvent, lambda x: L.append(x))
         instance.pid = 123
         instance.finish(123, 1)
-        self.assertEqual(instance.killing, 0)
+        self.assertFalse(instance.killing)
         self.assertEqual(instance.pid, 0)
         self.assertEqual(options.parent_pipes_closed, pipes)
         self.assertEqual(instance.pipes, {})
@@ -867,7 +867,48 @@ def test_finish_expected(self):
         self.assertEqual(event.extra_values, [('expected', True), ('pid', 123)])
         self.assertEqual(event.from_state, ProcessStates.RUNNING)
 
-    def test_finish_tooquickly(self):
+    def test_finish_starting_state_laststart_in_future(self):
+        options = DummyOptions()
+        config = DummyPConfig(options, 'notthere', '/notthere',
+                              stdout_logfile='/tmp/foo')
+        instance = self._makeOne(config)
+        instance.config.options.pidhistory[123] = instance
+        pipes = {'stdout':'','stderr':''}
+        instance.pipes = pipes
+        instance.config.exitcodes =[-1]
+        instance.laststart = time.time() + 3600 # 1 hour into the future
+        from supervisor.states import ProcessStates
+        from supervisor import events
+        instance.state = ProcessStates.STARTING
+        L = []
+        events.subscribe(events.ProcessStateEvent, lambda x: L.append(x))
+        instance.pid = 123
+        instance.finish(123, 1)
+        self.assertFalse(instance.killing)
+        self.assertEqual(instance.pid, 0)
+        self.assertEqual(options.parent_pipes_closed, pipes)
+        self.assertEqual(instance.pipes, {})
+        self.assertEqual(instance.dispatchers, {})
+        self.assertEqual(options.logger.data[0],
+                         "process 'notthere' (123) laststart time is in the "
+                         "future, don't know how long process was running so "
+                         "assuming it did not exit too quickly")
+        self.assertEqual(options.logger.data[1],
+                         'exited: notthere (terminated by SIGHUP; expected)')
+        self.assertEqual(instance.exitstatus, -1)
+        self.assertEqual(len(L), 2)
+        event = L[0]
+        self.assertEqual(event.__class__, events.ProcessStateRunningEvent)
+        self.assertEqual(event.expected, True)
+        self.assertEqual(event.extra_values, [('pid', 123)])
+        self.assertEqual(event.from_state, ProcessStates.STARTING)
+        event = L[1]
+        self.assertEqual(event.__class__, events.ProcessStateExitedEvent)
+        self.assertEqual(event.expected, True)
+        self.assertEqual(event.extra_values, [('expected', True), ('pid', 123)])
+        self.assertEqual(event.from_state, ProcessStates.RUNNING)
+
+    def test_finish_starting_state_exited_too_quickly(self):
         options = DummyOptions()
         config = DummyPConfig(options, 'notthere', '/notthere',
                               stdout_logfile='/tmp/foo', startsecs=10)
@@ -876,7 +917,6 @@ def test_finish_tooquickly(self):
         pipes = {'stdout':'','stderr':''}
         instance.pipes = pipes
         instance.config.exitcodes =[-1]
-        import time
         instance.laststart = time.time()
         from supervisor.states import ProcessStates
         from supervisor import events
@@ -885,7 +925,7 @@ def test_finish_tooquickly(self):
         events.subscribe(events.ProcessStateEvent, lambda x: L.append(x))
         instance.pid = 123
         instance.finish(123, 1)
-        self.assertEqual(instance.killing, 0)
+        self.assertFalse(instance.killing)
         self.assertEqual(instance.pid, 0)
         self.assertEqual(options.parent_pipes_closed, pipes)
         self.assertEqual(instance.pipes, {})
@@ -898,6 +938,43 @@ def test_finish_tooquickly(self):
         self.assertEqual(event.__class__, events.ProcessStateBackoffEvent)
         self.assertEqual(event.from_state, ProcessStates.STARTING)
 
+    def test_finish_running_state_laststart_in_future(self):
+        options = DummyOptions()
+        config = DummyPConfig(options, 'notthere', '/notthere',
+                              stdout_logfile='/tmp/foo')
+        instance = self._makeOne(config)
+        instance.config.options.pidhistory[123] = instance
+        pipes = {'stdout':'','stderr':''}
+        instance.pipes = pipes
+        instance.config.exitcodes =[-1]
+        instance.laststart = time.time() + 3600 # 1 hour into the future
+        from supervisor.states import ProcessStates
+        from supervisor import events
+        instance.state = ProcessStates.RUNNING
+        L = []
+        events.subscribe(events.ProcessStateEvent, lambda x: L.append(x))
+        instance.pid = 123
+        instance.finish(123, 1)
+        self.assertFalse(instance.killing)
+        self.assertEqual(instance.pid, 0)
+        self.assertEqual(options.parent_pipes_closed, pipes)
+        self.assertEqual(instance.pipes, {})
+        self.assertEqual(instance.dispatchers, {})
+        self.assertEqual(options.logger.data[0],
+                         "process 'notthere' (123) laststart time is in the "
+                         "future, don't know how long process was running so "
+                         "assuming it did not exit too quickly")
+        self.assertEqual(options.logger.data[1],
+                         'exited: notthere (terminated by SIGHUP; expected)')
+        self.assertEqual(instance.exitstatus, -1)
+        self.assertEqual(len(L), 1)
+        event = L[0]
+        self.assertEqual(event.__class__,
+                         events.ProcessStateExitedEvent)
+        self.assertEqual(event.expected, True)
+        self.assertEqual(event.extra_values, [('expected', True), ('pid', 123)])
+        self.assertEqual(event.from_state, ProcessStates.RUNNING)
+
     def test_finish_with_current_event_sends_rejected(self):
         from supervisor import events
         L = []