This variable specifies a command that filters build log output to a log file. The plan is to extend this to support a separate filter for tty output in the future.
In order to enable the EbuildPhase class to write elog messages to the build log with PORTAGE_LOG_FILTER_FILE support, convert its _elog method to a coroutine, and add a SchedulerInterface async_output method for it to use. Bug: https://bugs.gentoo.org/709746 Signed-off-by: Zac Medico <zmed...@gentoo.org> --- [PATCH v2] SpawnProcess and BuildLogger now have _run coroutine lib/_emerge/AbstractEbuildProcess.py | 2 + lib/_emerge/EbuildPhase.py | 21 +++- lib/_emerge/SpawnProcess.py | 28 ++++- .../ebuild/_config/special_env_vars.py | 6 +- lib/portage/util/_async/BuildLogger.py | 109 ++++++++++++++++++ lib/portage/util/_async/SchedulerInterface.py | 30 +++++ man/make.conf.5 | 4 + 7 files changed, 189 insertions(+), 11 deletions(-) create mode 100644 lib/portage/util/_async/BuildLogger.py diff --git a/lib/_emerge/AbstractEbuildProcess.py b/lib/_emerge/AbstractEbuildProcess.py index d1a6d1c4e..3732f80ed 100644 --- a/lib/_emerge/AbstractEbuildProcess.py +++ b/lib/_emerge/AbstractEbuildProcess.py @@ -181,6 +181,8 @@ class AbstractEbuildProcess(SpawnProcess): null_fd = os.open('/dev/null', os.O_RDONLY) self.fd_pipes[0] = null_fd + self.log_filter_file = self.settings.get('PORTAGE_LOG_FILTER_FILE') + try: yield SpawnProcess._async_start(self) finally: diff --git a/lib/_emerge/EbuildPhase.py b/lib/_emerge/EbuildPhase.py index 63d0746da..41ab79e53 100644 --- a/lib/_emerge/EbuildPhase.py +++ b/lib/_emerge/EbuildPhase.py @@ -26,6 +26,7 @@ from portage.package.ebuild.prepare_build_dirs import (_prepare_workdir, from portage.util.futures.compat_coroutine import coroutine, coroutine_return from portage.util import writemsg from portage.util._async.AsyncTaskFuture import AsyncTaskFuture +from portage.util._async.BuildLogger import BuildLogger from portage.util.futures.executor.fork import ForkExecutor try: @@ -130,7 +131,7 @@ class EbuildPhase(CompositeTask): # Force background=True for this header since it's intended # for the log and it doesn't necessarily need to be visible # elsewhere. - self._elog('einfo', msg, background=True) + yield self._elog('einfo', msg, background=True) if self.phase == 'package': if 'PORTAGE_BINPKG_TMPFILE' not in self.settings: @@ -392,6 +393,7 @@ class EbuildPhase(CompositeTask): self.returncode = 1 self.wait() + @coroutine def _elog(self, elog_funcname, lines, background=None): if background is None: background = self.background @@ -408,12 +410,25 @@ class EbuildPhase(CompositeTask): portage.output.havecolor = global_havecolor msg = out.getvalue() if msg: + build_logger = None + log_file = None log_path = None if self.settings.get("PORTAGE_BACKGROUND") != "subprocess": log_path = self.settings.get("PORTAGE_LOG_FILE") - self.scheduler.output(msg, log_path=log_path, + if log_path: + build_logger = BuildLogger(env=self.settings.environ(), + log_path=log_path, + log_filter_file=self.settings.get('PORTAGE_LOG_FILTER_FILE'), + scheduler=self.scheduler) + yield build_logger.async_start() + log_file = build_logger.stdin + + yield self.scheduler.async_output(msg, log_file=log_file, background=background) + if build_logger is not None: + build_logger.stdin.close() + yield build_logger.async_wait() class _PostPhaseCommands(CompositeTask): @@ -481,4 +496,4 @@ class _PostPhaseCommands(CompositeTask): qa_msg.extend("\t%s: %s" % (filename, " ".join(sorted(soname_deps))) for filename, soname_deps in unresolved) qa_msg.append("") - self.elog("eqawarn", qa_msg) + yield self.elog("eqawarn", qa_msg) diff --git a/lib/_emerge/SpawnProcess.py b/lib/_emerge/SpawnProcess.py index cda615ded..e06e2b934 100644 --- a/lib/_emerge/SpawnProcess.py +++ b/lib/_emerge/SpawnProcess.py @@ -19,6 +19,7 @@ from portage.const import BASH_BINARY from portage.localization import _ from portage.output import EOutput from portage.util import writemsg_level +from portage.util._async.BuildLogger import BuildLogger from portage.util._async.PipeLogger import PipeLogger from portage.util.futures import asyncio from portage.util.futures.compat_coroutine import coroutine @@ -36,7 +37,7 @@ class SpawnProcess(SubProcess): "path_lookup", "pre_exec", "close_fds", "cgroup", "unshare_ipc", "unshare_mount", "unshare_pid", "unshare_net") - __slots__ = ("args",) + \ + __slots__ = ("args", "log_filter_file") + \ _spawn_kwarg_names + ("_main_task", "_selinux_type",) # Max number of attempts to kill the processes listed in cgroup.procs, @@ -142,21 +143,36 @@ class SpawnProcess(SubProcess): fcntl.fcntl(stdout_fd, fcntl.F_GETFD) | fcntl.FD_CLOEXEC) + build_logger = BuildLogger(env=self.env, + log_path=log_file_path, + log_filter_file=self.log_filter_file, + scheduler=self.scheduler) + + yield build_logger.async_start() + pipe_logger = PipeLogger(background=self.background, scheduler=self.scheduler, input_fd=master_fd, - log_file_path=log_file_path, + log_file_path=build_logger.stdin, stdout_fd=stdout_fd) self._registered = True yield pipe_logger.async_start() self._main_task = asyncio.ensure_future( - self._main(pipe_logger), loop=self.scheduler) + self._main(pipe_logger, build_logger=build_logger), loop=self.scheduler) self._main_task.add_done_callback(self._main_exit) @coroutine - def _main(self, pipe_logger): - if pipe_logger.poll() is None: - yield pipe_logger.async_wait() + def _main(self, pipe_logger, build_logger=None): + try: + if pipe_logger.poll() is None: + yield pipe_logger.async_wait() + except Exception: + if build_logger is not None and build_logger.poll() is None: + build_logger.cancel() + raise + + if build_logger is not None and build_logger.poll() is None: + yield build_logger.async_wait() def _main_exit(self, main_task): try: diff --git a/lib/portage/package/ebuild/_config/special_env_vars.py b/lib/portage/package/ebuild/_config/special_env_vars.py index dc01339f7..977245309 100644 --- a/lib/portage/package/ebuild/_config/special_env_vars.py +++ b/lib/portage/package/ebuild/_config/special_env_vars.py @@ -175,7 +175,7 @@ environ_filter += [ "PORTAGE_RO_DISTDIRS", "PORTAGE_RSYNC_EXTRA_OPTS", "PORTAGE_RSYNC_OPTS", "PORTAGE_RSYNC_RETRIES", "PORTAGE_SSH_OPTS", "PORTAGE_SYNC_STALE", - "PORTAGE_USE", + "PORTAGE_USE", "PORTAGE_LOG_FILTER_FILE", "PORTAGE_LOGDIR", "PORTAGE_LOGDIR_CLEAN", "QUICKPKG_DEFAULT_OPTS", "REPOMAN_DEFAULT_OPTS", "RESUMECOMMAND", "RESUMECOMMAND_FTP", @@ -204,7 +204,9 @@ default_globals = { 'PORTAGE_BZIP2_COMMAND': 'bzip2', } -validate_commands = ('PORTAGE_BZIP2_COMMAND', 'PORTAGE_BUNZIP2_COMMAND',) +validate_commands = ('PORTAGE_BZIP2_COMMAND', 'PORTAGE_BUNZIP2_COMMAND', + 'PORTAGE_LOG_FILTER_FILE', +) # To enhance usability, make some vars case insensitive # by forcing them to lower case. diff --git a/lib/portage/util/_async/BuildLogger.py b/lib/portage/util/_async/BuildLogger.py new file mode 100644 index 000000000..cb1f7d3f9 --- /dev/null +++ b/lib/portage/util/_async/BuildLogger.py @@ -0,0 +1,109 @@ +# Copyright 2020 Gentoo Authors +# Distributed under the terms of the GNU General Public License v2 + +from portage import os +from portage.util import shlex_split +from _emerge.AsynchronousTask import AsynchronousTask +from portage.util._async.PipeLogger import PipeLogger +from portage.util.futures import asyncio +from portage.util.futures.compat_coroutine import coroutine + + +class BuildLogger(AsynchronousTask): + """ + Write to a log file, with compression support provided by PipeLogger. + If the log_filter_file parameter is specified, then it is interpreted + as a command to execute which filters log output (see the + PORTAGE_LOG_FILTER_FILE variable in make.conf(5)). The stdin property + provides access to a binary file object (refers to a pipe) that log + content should be written to (usually redirected from subprocess + stdout and stderr streams). + """ + + __slots__ = ('env', 'log_path', 'log_filter_file', '_main_task', '_stdin') + + @property + def stdin(self): + return self._stdin + + def _start(self): + self.scheduler.run_until_complete(self._async_start()) + + @coroutine + def _async_start(self): + if self.log_path is not None: + log_filter_file = self.log_filter_file + if log_filter_file is not None: + split_value = shlex_split(log_filter_file) + log_filter_file = split_value if split_value else None + if log_filter_file: + filter_input, stdin = os.pipe() + log_input, filter_output = os.pipe() + try: + filter_proc = yield asyncio.create_subprocess_exec( + *log_filter_file, + env=self.env, + stdin=filter_input, + stdout=filter_output, + stderr=filter_output, + loop=self.scheduler) + except EnvironmentError: + # Maybe the command is missing or broken somehow... + os.close(filter_input) + os.close(stdin) + os.close(log_input) + os.close(filter_output) + else: + self._stdin = os.fdopen(stdin, 'wb', 0) + os.close(filter_input) + os.close(filter_output) + # Create a PipeLogger instance to read output from + # filter_proc and log it. Set background=True + # so that this instance does not log to stdout. + pipe_logger = PipeLogger(background=True, + scheduler=self.scheduler, input_fd=log_input, + log_file_path=self.log_path) + yield pipe_logger.async_start() + self._main_task = asyncio.ensure_future( + self._main(pipe_logger, filter_proc=filter_proc), loop=self.scheduler) + self._main_task.add_done_callback(self._main_exit) + + if self._stdin is None: + # Since log_filter_file is unspecified or refers to a file + # that is missing or broken somehow, create a pipe that + # logs directly to a PipeLogger instance. + log_input, stdin = os.pipe() + self._stdin = os.fdopen(stdin, 'wb', 0) + pipe_logger = PipeLogger(background=True, + scheduler=self.scheduler, input_fd=log_input, + log_file_path=self.log_path) + yield pipe_logger.async_start() + self._main_task = asyncio.ensure_future( + self._main(pipe_logger), loop=self.scheduler) + self._main_task.add_done_callback(self._main_exit) + + def _cancel(self): + if self._main_task is not None: + self._main_task.cancel() + + @coroutine + def _main(self, pipe_logger, filter_proc=None): + try: + if pipe_logger.poll() is None: + yield pipe_logger.async_wait() + except Exception: + if filter_proc is not None and filter_proc.returncode is None: + filter_proc.terminate() + raise + + if filter_proc is not None and filter_proc.returncode is None: + yield filter_proc.wait() + + def _main_exit(self, main_task): + try: + main_task.result() + except asyncio.CancelledError: + self.cancel() + self._was_cancelled() + self.returncode = self.returncode or 0 + self._async_wait() diff --git a/lib/portage/util/_async/SchedulerInterface.py b/lib/portage/util/_async/SchedulerInterface.py index ec6417da1..1a9599d6f 100644 --- a/lib/portage/util/_async/SchedulerInterface.py +++ b/lib/portage/util/_async/SchedulerInterface.py @@ -7,6 +7,8 @@ import errno from portage import _encodings from portage import _unicode_encode from portage.util import writemsg_level +from portage.util.futures._asyncio.streams import _writer +from portage.util.futures.compat_coroutine import coroutine from ..SlotObject import SlotObject class SchedulerInterface(SlotObject): @@ -53,6 +55,34 @@ class SchedulerInterface(SlotObject): def _return_false(): return False + @coroutine + def async_output(self, msg, log_file=None, background=None, + level=0, noiselevel=-1): + """ + Output a msg to stdio (if not in background) and to a log file + if provided. + + @param msg: a message string, including newline if appropriate + @type msg: str + @param log_file: log file in binary mode + @type log_file: file + @param background: send messages only to log (not to stdio) + @type background: bool + @param level: a numeric logging level (see the logging module) + @type level: int + @param noiselevel: passed directly to writemsg + @type noiselevel: int + """ + global_background = self._is_background() + if background is None or global_background: + background = global_background + + if not background: + writemsg_level(msg, level=level, noiselevel=noiselevel) + + if log_file is not None: + yield _writer(log_file, _unicode_encode(msg)) + def output(self, msg, log_path=None, background=None, level=0, noiselevel=-1): """ diff --git a/man/make.conf.5 b/man/make.conf.5 index f82fed65a..69bfa6cdf 100644 --- a/man/make.conf.5 +++ b/man/make.conf.5 @@ -979,6 +979,10 @@ with an integer pid. For example, a value of "ionice \-c 3 \-p \\${PID}" will set idle io priority. For more information about ionice, see \fBionice\fR(1). This variable is unset by default. .TP +.B PORTAGE_LOG_FILTER_FILE +This variable specifies a command that filters build log output to a +log file. +.TP .B PORTAGE_LOGDIR This variable defines the directory in which per\-ebuild logs are kept. Logs are created only when this is set. They are stored as -- 2.24.1
