[checkmk-commits] Reworked output handling of background job processes

Module: check_mk Branch: master Commit: 83aa0342ebc1675148d0d9da0ffb9599a027cc24 URL: http://git.mathias-kettner.de/git/?p=check_mk.git;a=commit;h=83aa0342ebc167… Author: Lars Michelsen <lm(a)mathias-kettner.de> Date: Mon Aug 27 20:32:55 2018 +0200 Reworked output handling of background job processes * The output of background jobs was previously handled like this: stdout: Was set to a IO buffer object which was written from the executing function (in the executing thread) and continuously read from the main thread for writing it to the process status file. The underlying stdout file descriptor was not set which means that the output of subprocesses or libraries (e.g. libldap debug output) was not captured. stderr: Was also captured using an IO buffer and transported to var/log/web.log of the site instead of logging it to the job output. The underlying stdout file descriptor was not set which means that the output of subprocesses or libraries (e.g. libldap debug output) was not captured. * Now both, stdout and stderr, are set to a tempfile.TemporaryFile() sys.stdout and sys.stderr are set and also the FDs 1 and 2 are set. This means that all output of the background job is written to the temporary file. It is continuously read from the main thread of the background job and written to the status file. * The logging produced by the background job, which normally goes to var/log/web.log is now also written to stdout which is finally shown in the progress info. Change-Id: I6a674e2469479fa838f3933bf9f90c40a793eb88 --- cmk/gui/background_job.py | 53 +++++++++++++++++++++++++++-------------------- 1 file changed, 30 insertions(+), 23 deletions(-) diff --git a/cmk/gui/background_job.py b/cmk/gui/background_job.py index 1b7a433..5de69b2 100644 --- a/cmk/gui/background_job.py +++ b/cmk/gui/background_job.py @@ -28,14 +28,16 @@ import os import sys import time +import tempfile import pprint import threading import multiprocessing -from cStringIO import StringIO +import io import psutil import shutil import signal import traceback +import logging from cmk.gui.i18n import _ from cmk.gui.globals import html @@ -213,8 +215,8 @@ class BackgroundProcess(multiprocessing.Process): if not self._logger: self._logger = cmk.log.logger - sys.stderr = StreamLogger(self._logger, cmk.log.ERROR) - sys.stdout = StringIO() + self._open_stdout_and_stderr() + self._enable_logging_to_stdout() self._job_parameters["logger"] = self._logger @@ -223,15 +225,16 @@ class BackgroundProcess(multiprocessing.Process): def _execute_function(self): - # The specific function is called in a separate thread - # The main thread collects the stdout from the function-thread and updates the status file accordingly + # The specific function is called in a separate thread The main thread + # collects the output produced by the function-thread and updates the + # status file accordingly t = threading.Thread(target=self._call_function_with_exception_handling, args=[self._job_parameters]) t.start() last_progress_info = "" while t.isAlive(): time.sleep(0.2) - progress_info = sys.stdout.getvalue() # pylint: disable=no-member + progress_info = self._read_output() if progress_info != last_progress_info: self._jobstatus.update_status({"progress_info": BackgroundProcessInterface.parse_progress_info(progress_info)}) last_progress_info = progress_info @@ -239,8 +242,7 @@ class BackgroundProcess(multiprocessing.Process): # Final progress info update job_status_update = {} - progress_info = sys.stdout.getvalue() # pylint: disable=no-member - + progress_info = self._read_output() if progress_info != last_progress_info: job_status_update.update({"progress_info": BackgroundProcessInterface.parse_progress_info(progress_info)}) @@ -272,25 +274,27 @@ class BackgroundProcess(multiprocessing.Process): job_interface.send_exception(_("Exception: %s") % (e)) - -# TODO(ab): Wouldn't it be better to also write the stderr to the job results instead of just writing -# it to the web.log? -class StreamLogger(object): - """File like stream object to redirects writes to the given logger""" - def __init__(self, logger, level): - super(StreamLogger, self).__init__() - self._logger = logger - self._level = level - self._linebuf = '' + def _open_stdout_and_stderr(self): + """Create a temporary file and use it as stdout / stderr buffer""" + # We can not use io.BytesIO() or similar because we need real file descriptors + # to be able to catch the (debug) output of libraries like libldap or subproccesses + sys.stdout = sys.stderr = tempfile.TemporaryFile(mode='w+b') + os.dup2(sys.stdout.fileno(), 1) + os.dup2(sys.stderr.fileno(), 2) - def write(self, buf): - for line in buf.rstrip().splitlines(): - self._logger.log(self._level, line.rstrip()) + def _read_output(self): + sys.stderr.flush() + sys.stderr.seek(0, io.SEEK_SET) + return sys.stderr.read() - def flush(self): - pass + def _enable_logging_to_stdout(self): + """In addition to the web.log we also want to see the job specific logs + in stdout (which results in job progress info)""" + handler = logging.StreamHandler(stream=sys.stdout) + handler.setFormatter(cmk.log.get_formatter()) + cmk.log.logger.addHandler(handler) @@ -521,6 +525,9 @@ class BackgroundJob(object): p.start() p.join() + job_status = self.get_status() + self._logger.debug("Started job \"%s\" (PID: %d)" % (self._job_id, job_status["pid"])) + def _start_background_subprocess(self, job_parameters): try: