From 423cfc5baf9cd92400e4159f201bffdf3fd7b2b3 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 | 56 ++++++++++++++++++ supervisor/process.py | 26 +++++---- supervisor/tests/test_process.py | 97 ++++++++++++++++++++++++++++---- 3 files changed, 159 insertions(+), 20 deletions(-) diff --git a/CHANGES.txt b/CHANGES.txt index 45bd55547..2d5ebac76 100644 --- 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 ``hello`` but not strings like + ``hello``, 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 index 2b3c59396..f495931df 100644 --- 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 index 7dc3d2c79..4b977d13c 100644 --- 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 = []