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

Fixes #281
Fixes #458
Fixes #533
Fixes #552
Fixes #618

CHANGES.txt

@@ -23,6 +23,11 @@
 - 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.

supervisor/process.py

@@ -453,7 +453,15 @@ class Subprocess:
         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:
@@ -467,7 +475,7 @@ class Subprocess:
             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
@@ -478,18 +486,16 @@ class Subprocess:
 
         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)

supervisor/tests/test_process.py

@@ -898,24 +898,24 @@ class SubprocessTests(unittest.TestCase):
         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, {})
@@ -929,7 +929,7 @@ class SubprocessTests(unittest.TestCase):
         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')
@@ -942,10 +942,10 @@ class SubprocessTests(unittest.TestCase):
         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, {})
@@ -961,7 +961,48 @@ class SubprocessTests(unittest.TestCase):
         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)
@@ -970,7 +1011,6 @@ class SubprocessTests(unittest.TestCase):
         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
@@ -979,7 +1019,7 @@ class SubprocessTests(unittest.TestCase):
         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, {})
@@ -992,6 +1032,43 @@ class SubprocessTests(unittest.TestCase):
         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 = []