[checkmk-commits] Background jobs: Fixed stop signal handling

Module: check_mk Branch: master Commit: 915e51e2dc4da0d4ef831bf2d39d2c727e760b7f URL: http://git.mathias-kettner.de/git/?p=check_mk.git;a=commit;h=915e51e2dc4da0… Author: Lars Michelsen <lm(a)mathias-kettner.de> Date: Sat Dec 15 20:10:32 2018 +0100 Background jobs: Fixed stop signal handling The stoppable background jobs could not be stopped in all situations in a clean way. The signal processing of the background process was prvented by a .join() on the execution thread which prevented the python signal handling from being executed when receiving a SIGTERM to stop the process. Cleaned up signal handling in the job process to use the MKTerminate exception raising up the call stack and make the top run() method set the final job state. Cleaned up logging on the way. Change-Id: I7430a2ad2188dcb00c94437922eeb0866cec664a --- cmk/gui/background_job.py | 30 +++++---- cmk/gui/gui_background_job.py | 3 +- tests/unit/cmk/gui/test_background_job.py | 108 ++++++++++++++++++++++++++++++ 3 files changed, 126 insertions(+), 15 deletions(-) diff --git a/cmk/gui/background_job.py b/cmk/gui/background_job.py index 888e020..2945844 100644 --- a/cmk/gui/background_job.py +++ b/cmk/gui/background_job.py @@ -35,7 +35,7 @@ import threading import time import traceback -import psutil +import psutil # type: ignore from pathlib2 import Path from cmk.gui.i18n import _ @@ -43,7 +43,7 @@ import cmk import cmk.log import cmk.daemon as daemon import cmk.store as store -from cmk.exceptions import MKGeneralException +from cmk.exceptions import MKGeneralException, MKTerminate import cmk.gui.log @@ -131,9 +131,8 @@ class BackgroundProcess(BackgroundProcessInterface, multiprocessing.Process): def __init__(self, job_parameters): super(BackgroundProcess, self).__init__(job_parameters) self._jobstatus = self._job_parameters["jobstatus"] - self._logger = None # the logger is initialized in the run function - - self._register_signal_handlers() + # TODO: Hand over the logger via arguments + self._logger = cmk.gui.log.logger.getChild("background_process") def _register_signal_handlers(self): signal.signal(signal.SIGTERM, self._handle_sigterm) @@ -145,8 +144,7 @@ class BackgroundProcess(BackgroundProcessInterface, multiprocessing.Process): self._job_parameters["job_id"], status["pid"]) return - self._jobstatus.update_status({"state": JobStatus.state_stopped}) - os._exit(0) + raise MKTerminate() def run(self): # Detach from parent (apache) -> Remain running when apache is restarted @@ -168,17 +166,18 @@ class BackgroundProcess(BackgroundProcessInterface, multiprocessing.Process): # The actual function call self._execute_function() + except MKTerminate: + self._logger.warning("Job was stopped") + self._jobstatus.update_status({"state": JobStatus.state_stopped}) except Exception: self._logger.error( "Exception while preparing background function environment", exc_info=True) self._jobstatus.update_status({"state": JobStatus.state_exception}) def initialize_environment(self): - if not self._logger: - self._logger = cmk.gui.log.logger - self._open_stdout_and_stderr() self._enable_logging_to_stdout() + self._register_signal_handlers() self._job_parameters["logger"] = self._logger @@ -190,8 +189,9 @@ class BackgroundProcess(BackgroundProcessInterface, multiprocessing.Process): target=self._call_function_with_exception_handling, args=[self._job_parameters]) t.start() - # Wait for thread to finish - t.join() + # Wait for thread to finish. Do the join with timeout to be able to handle signals + while t.is_alive(): + t.join(0.5) # Final progress info update job_status_update = {} @@ -202,7 +202,6 @@ class BackgroundProcess(BackgroundProcessInterface, multiprocessing.Process): final_state = JobStatus.state_exception else: final_state = JobStatus.state_finished - job_status_update.update({ "state": final_state, "duration": time.time() - job_status["started"], @@ -220,9 +219,11 @@ class BackgroundProcess(BackgroundProcessInterface, multiprocessing.Process): try: func_ptr(*args, **kwargs) + except MKTerminate: + raise except Exception as e: logger = job_interface.get_logger() - logger.error("Exception in background function:\n%s" % (traceback.format_exc())) + logger.error("Exception in background function", exc_info=True) job_interface.send_exception(_("Exception: %s") % (e)) def _open_stdout_and_stderr(self): @@ -492,6 +493,7 @@ class BackgroundJob(object): self._jobstatus.update_status({"pid": p.pid}) except Exception as e: self._logger.error("Error while starting subprocess: %s" % e) + os._exit(1) os._exit(0) diff --git a/cmk/gui/gui_background_job.py b/cmk/gui/gui_background_job.py index 5a7af86..e8ed362 100644 --- a/cmk/gui/gui_background_job.py +++ b/cmk/gui/gui_background_job.py @@ -113,7 +113,8 @@ class GUIBackgroundProcess(background_job.BackgroundProcess): self._log_path_hint = _("More information can be found in ~/var/log/web.log") # Disable html request timeout - html.disable_request_timeout() + if html.in_html_context(): + html.disable_request_timeout() # Close livestatus connections inherited from the parent process sites.disconnect() diff --git a/tests/unit/cmk/gui/test_background_job.py b/tests/unit/cmk/gui/test_background_job.py new file mode 100644 index 0000000..f7e803d --- /dev/null +++ b/tests/unit/cmk/gui/test_background_job.py @@ -0,0 +1,108 @@ +import time +import signal +import sys +import pytest # type: ignore +from pathlib2 import Path +import testlib # type: ignore + +import cmk.paths +import cmk.gui.background_job as background_job +import cmk.gui.gui_background_job as gui_background_job + +import cmk.gui.log + + +(a)pytest.fixture(autouse=True) +def debug_logging(): + cmk.gui.log.set_log_levels({"cmk.web": cmk.gui.log._logging.DEBUG}) + yield + cmk.gui.log.set_log_levels({"cmk.web": cmk.gui.log._logging.WARNING}) + + +(a)pytest.fixture(autouse=True) +def job_base_dir(tmpdir, monkeypatch): + var_dir = Path("%s" % tmpdir) + + log_dir = var_dir / "log" + log_dir.mkdir() # pylint: disable=no-member + + job_dir = var_dir / "background_jobs" + job_dir.mkdir() # pylint: disable=no-member + + # Patch for web.log. Sholdn't we do this for all web tests? + monkeypatch.setattr(cmk.paths, "log_dir", str(log_dir)) + + monkeypatch.setattr(background_job.BackgroundJobDefines, "base_dir", str(job_dir)) + return job_dir + + +(a)gui_background_job.job_registry.register +class DummyBackgroundJob(gui_background_job.GUIBackgroundJob): + job_prefix = "dummy_job" + gui_title = u"Dummy Job" + + def __init__(self): + kwargs = {} + kwargs["title"] = self.gui_title + kwargs["deletable"] = False + kwargs["stoppable"] = True + + super(DummyBackgroundJob, self).__init__(self.job_prefix, **kwargs) + + def execute_hello(self, job_interface): + sys.stdout.write("Hallo :-)\n") + sys.stdout.flush() + + def execute_endless(self): + sys.stdout.write("Hanging loop\n") + sys.stdout.flush() + time.sleep(100) + + +def test_start_job(): + job = DummyBackgroundJob() + job.set_function(job.execute_hello) + + status = job.get_status() + assert status["state"] == background_job.JobStatus.state_initialized + + job.start() + assert job.is_running() + + with pytest.raises(background_job.BackgroundJobAlreadyRunning): + job.start() + assert job.is_running() + + testlib.wait_until( + lambda: job.get_status()["state"] not in [ background_job.JobStatus.state_initialized, background_job.JobStatus.state_running ], + timeout=5, + interval=0.1) + + status = job.get_status() + assert status["state"] == background_job.JobStatus.state_finished + + output = "\n".join(status["loginfo"]["JobProgressUpdate"]) + assert "Initialized background job" in output + assert "Hallo :-)" in output + + +def test_stop_job(): + job = DummyBackgroundJob() + job.set_function(job.execute_endless) + job.start() + + testlib.wait_until( + lambda: "Hanging loop" in job.get_status()["loginfo"]["JobProgressUpdate"], + timeout=5, + interval=0.1) + + status = job.get_status() + assert status["state"] == background_job.JobStatus.state_running + + job.stop() + + status = job.get_status() + assert status["state"] == background_job.JobStatus.state_stopped + + output = "\n".join(status["loginfo"]["JobProgressUpdate"]) + assert "Job was stopped" in output