commit: 73f72f526a66b9953a46868cc1390fde2820997f Author: Zac Medico <zmedico <AT> gentoo <DOT> org> AuthorDate: Sun Mar 1 02:17:52 2020 +0000 Commit: Zac Medico <zmedico <AT> gentoo <DOT> org> CommitDate: Sun Mar 1 04:29:41 2020 +0000 URL: https://gitweb.gentoo.org/proj/portage.git/commit/?id=73f72f52
Support PORTAGE_LOG_FILTER_FILE (bug 709746) 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 <zmedico <AT> gentoo.org> lib/_emerge/AbstractEbuildProcess.py | 2 + lib/_emerge/EbuildPhase.py | 36 +++++-- lib/_emerge/SpawnProcess.py | 32 ++++-- .../package/ebuild/_config/special_env_vars.py | 8 +- lib/portage/util/_async/BuildLogger.py | 116 +++++++++++++++++++++ lib/portage/util/_async/SchedulerInterface.py | 32 +++++- man/make.conf.5 | 7 +- 7 files changed, 213 insertions(+), 20 deletions(-) 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 f6b380e05..927a74b98 100644 --- a/lib/_emerge/EbuildPhase.py +++ b/lib/_emerge/EbuildPhase.py @@ -26,6 +26,8 @@ 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 import asyncio from portage.util.futures.executor.fork import ForkExecutor try: @@ -130,7 +132,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 +394,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,11 +411,30 @@ class EbuildPhase(CompositeTask): portage.output.havecolor = global_havecolor msg = out.getvalue() if msg: - 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, - background=background) + build_logger = None + try: + log_file = None + log_path = None + if self.settings.get("PORTAGE_BACKGROUND") != "subprocess": + log_path = self.settings.get("PORTAGE_LOG_FILE") + 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() + except asyncio.CancelledError: + if build_logger is not None: + build_logger.cancel() + raise class _PostPhaseCommands(CompositeTask): @@ -481,4 +503,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 ab7971ca8..34668b287 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,30 +143,45 @@ class SpawnProcess(SubProcess): fcntl.fcntl(stdout_fd, fcntl.F_GETFD) | fcntl.FD_CLOEXEC) - pipe_logger = PipeLogger(background=self.background, - scheduler=self.scheduler, input_fd=master_fd, - log_file_path=log_file_path, - stdout_fd=stdout_fd) + build_logger = BuildLogger(env=self.env, + log_path=log_file_path, + log_filter_file=self.log_filter_file, + scheduler=self.scheduler) + self._registered = True + pipe_logger = None try: + yield build_logger.async_start() + + pipe_logger = PipeLogger(background=self.background, + scheduler=self.scheduler, input_fd=master_fd, + log_file_path=build_logger.stdin, + stdout_fd=stdout_fd) + yield pipe_logger.async_start() except asyncio.CancelledError: - if pipe_logger.poll() is None: + if pipe_logger is not None and pipe_logger.poll() is None: pipe_logger.cancel() + if build_logger.poll() is None: + build_logger.cancel() raise self._main_task = asyncio.ensure_future( - self._main(pipe_logger), loop=self.scheduler) + self._main(pipe_logger, build_logger), loop=self.scheduler) self._main_task.add_done_callback(self._main_exit) @coroutine - def _main(self, pipe_logger): + def _main(self, pipe_logger, build_logger): try: if pipe_logger.poll() is None: yield pipe_logger.async_wait() + if build_logger.poll() is None: + yield build_logger.async_wait() except asyncio.CancelledError: if pipe_logger.poll() is None: pipe_logger.cancel() + if build_logger.poll() is None: + build_logger.cancel() raise def _main_exit(self, main_task): diff --git a/lib/portage/package/ebuild/_config/special_env_vars.py b/lib/portage/package/ebuild/_config/special_env_vars.py index dc01339f7..dd8105123 100644 --- a/lib/portage/package/ebuild/_config/special_env_vars.py +++ b/lib/portage/package/ebuild/_config/special_env_vars.py @@ -1,4 +1,4 @@ -# Copyright 2010-2019 Gentoo Authors +# Copyright 2010-2020 Gentoo Authors # Distributed under the terms of the GNU General Public License v2 from __future__ import unicode_literals @@ -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..4873d9750 --- /dev/null +++ b/lib/portage/util/_async/BuildLogger.py @@ -0,0 +1,116 @@ +# 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 writable binary file stream (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): + pipe_logger = None + filter_proc = None + try: + log_input = None + 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) + + 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 pipe_logger. + log_input, stdin = os.pipe() + self._stdin = os.fdopen(stdin, 'wb', 0) + + # Set background=True so that pipe_logger 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() + except asyncio.CancelledError: + if pipe_logger is not None and pipe_logger.poll() is None: + pipe_logger.cancel() + if filter_proc is not None and filter_proc.returncode is None: + filter_proc.terminate() + raise + + 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) + + def _cancel(self): + if self._main_task is not None: + self._main_task.done() or self._main_task.cancel() + if self._stdin is not None and not self._stdin.closed: + self._stdin.close() + + @coroutine + def _main(self, pipe_logger, filter_proc=None): + try: + if pipe_logger.poll() is None: + yield pipe_logger.async_wait() + if filter_proc is not None and filter_proc.returncode is None: + yield filter_proc.wait() + except asyncio.CancelledError: + if pipe_logger.poll() is None: + pipe_logger.cancel() + if filter_proc is not None and filter_proc.returncode is None: + filter_proc.terminate() + raise + + 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..3ff250d1d 100644 --- a/lib/portage/util/_async/SchedulerInterface.py +++ b/lib/portage/util/_async/SchedulerInterface.py @@ -1,4 +1,4 @@ -# Copyright 2012-2018 Gentoo Foundation +# Copyright 2012-2020 Gentoo Authors # Distributed under the terms of the GNU General Public License v2 import gzip @@ -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..baecd283a 100644 --- a/man/make.conf.5 +++ b/man/make.conf.5 @@ -1,4 +1,4 @@ -.TH "MAKE.CONF" "5" "Nov 2019" "Portage VERSION" "Portage" +.TH "MAKE.CONF" "5" "Mar 2020" "Portage VERSION" "Portage" .SH "NAME" make.conf \- custom settings for Portage .SH "SYNOPSIS" @@ -979,6 +979,11 @@ 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. In order to filter ANSI escape codes from build logs, +\fBansifilter\fR(1) is a convenient setting for this variable. +.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
