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> --- lib/_emerge/AbstractEbuildProcess.py | 2 + lib/_emerge/EbuildPhase.py | 22 +++- lib/_emerge/SpawnProcess.py | 33 +++++- .../ebuild/_config/special_env_vars.py | 6 +- lib/portage/util/_async/BuildLogger.py | 103 ++++++++++++++++++ lib/portage/util/_async/SchedulerInterface.py | 30 +++++ man/make.conf.5 | 4 + 7 files changed, 191 insertions(+), 9 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..fd766e590 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,26 @@ 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: + if build_logger.stdin is not None: + build_logger.stdin.close() + yield build_logger.async_wait() class _PostPhaseCommands(CompositeTask): @@ -481,4 +497,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 ba58d9d0e..4d96ce9ed 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.compat_coroutine import coroutine @@ -35,8 +36,8 @@ class SpawnProcess(SubProcess): "path_lookup", "pre_exec", "close_fds", "cgroup", "unshare_ipc", "unshare_mount", "unshare_pid", "unshare_net") - __slots__ = ("args",) + \ - _spawn_kwarg_names + ("_pipe_logger", "_selinux_type",) + __slots__ = ("args", "log_filter_file") + \ + _spawn_kwarg_names + ("_build_logger", "_pipe_logger", "_selinux_type",) # Max number of attempts to kill the processes listed in cgroup.procs, # given that processes may fork before they can be killed. @@ -141,9 +142,17 @@ class SpawnProcess(SubProcess): fcntl.fcntl(stdout_fd, fcntl.F_GETFD) | fcntl.FD_CLOEXEC) + self._build_logger = BuildLogger(env=self.env, + log_path=log_file_path, + log_filter_file=self.log_filter_file, + scheduler=self.scheduler) + + self._build_logger.addExitListener(self._build_logger_exit) + yield self._build_logger.async_start() + self._pipe_logger = PipeLogger(background=self.background, scheduler=self.scheduler, input_fd=master_fd, - log_file_path=log_file_path, + log_file_path=self._build_logger.stdin, stdout_fd=stdout_fd) self._pipe_logger.addExitListener(self._pipe_logger_exit) self._registered = True @@ -173,13 +182,29 @@ class SpawnProcess(SubProcess): def _pipe_logger_exit(self, pipe_logger): self._pipe_logger = None - self._async_waitpid() + if self._build_logger is None: + self._async_waitpid() + + def _build_logger_exit(self, build_logger): + self._build_logger = None + if self._pipe_logger is None: + self._async_waitpid() + + def _async_waitpid(self): + if self._build_logger is not None: + # All output should have been collected by now, so kill it. + self._build_logger.cancel() + SubProcess._async_waitpid(self) def _unregister(self): SubProcess._unregister(self) if self.cgroup is not None: self._cgroup_cleanup() self.cgroup = None + if self._build_logger is not None: + self._build_logger.removeExitListener(self._build_logger_exit) + self._build_logger.cancel() + self._build_logger = None if self._pipe_logger is not None: self._pipe_logger.cancel() self._pipe_logger = None 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..04da17c78 --- /dev/null +++ b/lib/portage/util/_async/BuildLogger.py @@ -0,0 +1,103 @@ +# Copyright 2020 Gentoo Authors +# Distributed under the terms of the GNU General Public License v2 + +import portage +portage.proxy.lazyimport.lazyimport(globals(), + '_emerge.SpawnProcess:SpawnProcess', +) + +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.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', '_pipe_logger', '_filter_proc', '_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() + self._filter_proc = SpawnProcess( + args=log_filter_file, + env=self.env, + fd_pipes={0: filter_input, 1: filter_output, 2: filter_output}, + scheduler=self.scheduler) + try: + yield self._filter_proc.async_start() + except portage.exception.CommandNotFound: + self._filter_proc._unregister() + self._filter_proc = None + 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 + # self._filter_proc and log it. Set background=True + # so that this instance does not log to stdout. + self._pipe_logger = PipeLogger(background=True, + scheduler=self.scheduler, input_fd=log_input, + log_file_path=self.log_path) + yield self._pipe_logger.async_start() + + self._pipe_logger.async_wait().add_done_callback(self._pipe_logger_exit) + self._filter_proc.async_wait().add_done_callback(self._filter_proc_exit) + + if self._stdin is None: + # Since log_filter_file is unspecified or refers to a file that + # was not found, create a pipe that logs directly to a PipeLogger + # instance. + log_input, stdin = os.pipe() + self._stdin = os.fdopen(stdin, 'wb', 0) + self._pipe_logger = PipeLogger(background=True, + scheduler=self.scheduler, input_fd=log_input, + log_file_path=self.log_path) + yield self._pipe_logger.async_start() + self._pipe_logger.async_wait().add_done_callback(self._pipe_logger_exit) + + def _cancel(self): + if self._pipe_logger is not None and self._pipe_logger.poll() is None: + self._pipe_logger.cancel() + if self._filter_proc is not None and self._filter_proc.poll() is None: + self._filter_proc.cancel() + + def _pipe_logger_exit(self, future): + self._pipe_logger = None + if self._filter_proc is None: + self.returncode = 0 + self._async_wait() + + def _filter_proc_exit(self, future): + self._filter_proc = None + if self._pipe_logger is None: + self.returncode = 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
