From eb96a2afa1cb9edf4db5c6bf3f1941ed9bb0b833 Mon Sep 17 00:00:00 2001 From: Mike Naberezny Date: Sat, 13 Jun 2015 15:05:54 -0700 Subject: [PATCH] Fix AssertionError if subprocess exits after system time is set back. Fixes #281 Fixes #458 Fixes #533 Fixes #552 Fixes #618 --- CHANGES.txt | 5 ++ supervisor/process.py | 26 +++++---- supervisor/tests/test_process.py | 97 ++++++++++++++++++++++++++++---- 3 files changed, 108 insertions(+), 20 deletions(-) diff --git a/CHANGES.txt b/CHANGES.txt index c3fa1f1e8..1f3ee7051 100644 --- a/CHANGES.txt +++ b/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. diff --git a/supervisor/process.py b/supervisor/process.py index 70c31cf03..fba9f7217 100644 --- a/supervisor/process.py +++ b/supervisor/process.py @@ -453,7 +453,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: @@ -467,7 +475,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 @@ -478,18 +486,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 index b83f41e7c..21bb9ae7b 100644 --- a/supervisor/tests/test_process.py +++ b/supervisor/tests/test_process.py @@ -898,24 +898,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, {}) @@ -929,7 +929,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') @@ -942,10 +942,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, {}) @@ -961,7 +961,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) @@ -970,7 +1011,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 @@ -979,7 +1019,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, {}) @@ -992,6 +1032,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 = []