On Fri, 19 Jun 2020 13:39:19 -0700 Zac Medico <zmed...@gentoo.org> wrote:
> 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_CMD support, convert its > _elog method to a coroutine, and add a SchedulerInterface async_output > method for it to use. > > Use a new BuildLogger class to manage log output (with or without a > filter command), with compression support provided by PipeLogger. > BuildLogger has a stdin property which provides access to a writable > binary file stream (refers to a pipe) that log content is written to. > > Bug: https://bugs.gentoo.org/709746 > Signed-off-by: Zac Medico <zmed...@gentoo.org> > --- > lib/_emerge/AbstractEbuildProcess.py | 3 +- > lib/_emerge/BinpkgFetcher.py | 3 +- > lib/_emerge/EbuildFetcher.py | 3 +- > lib/_emerge/EbuildPhase.py | 47 ++++++-- > lib/_emerge/SpawnProcess.py | 58 +++++++--- > lib/portage/dbapi/_MergeProcess.py | 3 +- > .../ebuild/_config/special_env_vars.py | 8 +- > lib/portage/util/_async/BuildLogger.py | 109 > ++++++++++++++++++ lib/portage/util/_async/SchedulerInterface.py | > 32 ++++- man/make.conf.5 | 7 +- > 10 files changed, 243 insertions(+), 30 deletions(-) > create mode 100644 lib/portage/util/_async/BuildLogger.py > > diff --git a/lib/_emerge/AbstractEbuildProcess.py > b/lib/_emerge/AbstractEbuildProcess.py index 1c1955cfe..ae1aae55f > 100644 --- a/lib/_emerge/AbstractEbuildProcess.py > +++ b/lib/_emerge/AbstractEbuildProcess.py > @@ -1,4 +1,4 @@ > -# Copyright 1999-2019 Gentoo Foundation > +# Copyright 1999-2020 Gentoo Authors > # Distributed under the terms of the GNU General Public License v2 > > import errno > @@ -196,6 +196,7 @@ 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_CMD') try: > SpawnProcess._start(self) > finally: > diff --git a/lib/_emerge/BinpkgFetcher.py > b/lib/_emerge/BinpkgFetcher.py index 36d027de3..2e5861cc1 100644 > --- a/lib/_emerge/BinpkgFetcher.py > +++ b/lib/_emerge/BinpkgFetcher.py > @@ -1,4 +1,4 @@ > -# Copyright 1999-2018 Gentoo Foundation > +# Copyright 1999-2020 Gentoo Authors > # Distributed under the terms of the GNU General Public License v2 > > import functools > @@ -158,6 +158,7 @@ class _BinpkgFetcherProcess(SpawnProcess): > self.env = fetch_env > if settings.selinux_enabled(): > self._selinux_type = > settings["PORTAGE_FETCH_T"] > + self.log_filter_file = > settings.get('PORTAGE_LOG_FILTER_FILE_CMD') SpawnProcess._start(self) > > def _pipe(self, fd_pipes): > diff --git a/lib/_emerge/EbuildFetcher.py > b/lib/_emerge/EbuildFetcher.py index 1e40994fb..55349c33c 100644 > --- a/lib/_emerge/EbuildFetcher.py > +++ b/lib/_emerge/EbuildFetcher.py > @@ -1,4 +1,4 @@ > -# Copyright 1999-2018 Gentoo Foundation > +# Copyright 1999-2020 Gentoo Authors > # Distributed under the terms of the GNU General Public License v2 > > import copy > @@ -225,6 +225,7 @@ class _EbuildFetcherProcess(ForkProcess): > settings["NOCOLOR"] = nocolor > > self._settings = settings > + self.log_filter_file = > settings.get('PORTAGE_LOG_FILTER_FILE_CMD') ForkProcess._start(self) > > # Free settings now since it's no longer needed in > diff --git a/lib/_emerge/EbuildPhase.py b/lib/_emerge/EbuildPhase.py > index 477e0ba97..ddb3dc719 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 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: > @@ -69,6 +71,11 @@ class EbuildPhase(CompositeTask): > _locked_phases = ("setup", "preinst", "postinst", "prerm", > "postrm") > def _start(self): > + future = asyncio.ensure_future(self._async_start(), > loop=self.scheduler) > + self._start_task(AsyncTaskFuture(future=future), > self._async_start_exit) + > + @coroutine > + def _async_start(self): > > need_builddir = self.phase not in > EbuildProcess._phases_without_builddir > @@ -126,7 +133,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: @@ -134,6 +141,12 @@ class EbuildPhase(CompositeTask): > os.path.join(self.settings['PKGDIR'], > self.settings['CATEGORY'], > self.settings['PF']) + '.tbz2' > + def _async_start_exit(self, task): > + task.future.cancelled() or task.future.result() > + if self._default_exit(task) != os.EX_OK: > + self.wait() > + return > + > if self.phase in ("pretend", "prerm"): > env_extractor = > BinpkgEnvExtractor(background=self.background, > scheduler=self.scheduler, settings=self.settings) @@ -391,6 +404,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 > @@ -407,11 +421,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_CMD'), > + > scheduler=self.scheduler) > + build_logger.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): > @@ -480,4 +513,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 395d66bb9..f96911571 100644 > --- a/lib/_emerge/SpawnProcess.py > +++ b/lib/_emerge/SpawnProcess.py > @@ -1,4 +1,4 @@ > -# Copyright 2008-2018 Gentoo Foundation > +# Copyright 2008-2020 Gentoo Authors > # Distributed under the terms of the GNU General Public License v2 > > try: > @@ -19,7 +19,10 @@ 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 > > class SpawnProcess(SubProcess): > > @@ -34,8 +37,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 + ("_main_task", "_selinux_type",) > > # Max number of attempts to kill the processes listed in > cgroup.procs, # given that processes may fork before they can be > killed. @@ -137,13 +140,43 @@ class SpawnProcess(SubProcess): > fcntl.fcntl(stdout_fd, > fcntl.F_GETFD) | > fcntl.FD_CLOEXEC) > - self._pipe_logger = > PipeLogger(background=self.background, > + build_logger = BuildLogger(env=self.env, > + log_path=log_file_path, > + log_filter_file=self.log_filter_file, > + scheduler=self.scheduler) > + build_logger.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._pipe_logger.addExitListener(self._pipe_logger_exit) > - self._pipe_logger.start() > + > + pipe_logger.start() > + > self._registered = True > + self._main_task = > asyncio.ensure_future(self._main(build_logger, pipe_logger), > loop=self.scheduler) > + self._main_task.add_done_callback(self._main_exit) > + > + @coroutine > + def _main(self, build_logger, pipe_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): > + try: > + main_task.result() > + except asyncio.CancelledError: > + self.cancel() > + self._async_waitpid() > > def _can_log(self, slave_fd): > return True > @@ -167,20 +200,17 @@ class SpawnProcess(SubProcess): > > return spawn_func(args, **kwargs) > > - def _pipe_logger_exit(self, pipe_logger): > - self._pipe_logger = None > - self._async_waitpid() > - > def _unregister(self): > SubProcess._unregister(self) > if self.cgroup is not None: > self._cgroup_cleanup() > self.cgroup = None > - if self._pipe_logger is not None: > - self._pipe_logger.cancel() > - self._pipe_logger = None > + if self._main_task is not None: > + self._main_task.done() or > self._main_task.cancel() > def _cancel(self): > + if self._main_task is not None: > + self._main_task.done() or > self._main_task.cancel() SubProcess._cancel(self) > self._cgroup_cleanup() > > diff --git a/lib/portage/dbapi/_MergeProcess.py > b/lib/portage/dbapi/_MergeProcess.py index 371550079..236d1a255 100644 > --- a/lib/portage/dbapi/_MergeProcess.py > +++ b/lib/portage/dbapi/_MergeProcess.py > @@ -1,4 +1,4 @@ > -# Copyright 2010-2018 Gentoo Foundation > +# Copyright 2010-2020 Gentoo Authors > # Distributed under the terms of the GNU General Public License v2 > > import io > @@ -57,6 +57,7 @@ class MergeProcess(ForkProcess): > self.fd_pipes = self.fd_pipes.copy() > self.fd_pipes.setdefault(0, > portage._get_stdin().fileno()) > + self.log_filter_file = > self.settings.get('PORTAGE_LOG_FILTER_FILE_CMD') super(MergeProcess, > self)._start() > def _lock_vdb(self): > diff --git a/lib/portage/package/ebuild/_config/special_env_vars.py > b/lib/portage/package/ebuild/_config/special_env_vars.py index > 440dd00b2..f44cb9b1b 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_CMD", > "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_CMD', > +) > > # 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..f5fea77ea > --- /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 > + > +import subprocess > + > +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._async.PopenProcess import PopenProcess > +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_CMD 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): > + filter_proc = None > + 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 = PopenProcess( > + > proc=subprocess.Popen( > + > log_filter_file, > + env=self.env, > + > stdin=filter_input, > + > stdout=filter_output, > + > stderr=filter_output, > + ), > + > scheduler=self.scheduler, > + ) > + filter_proc.start() > + 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) > + pipe_logger.start() > + > + self._main_task = > asyncio.ensure_future(self._main(filter_proc, pipe_logger), > loop=self.scheduler) > + self._main_task.add_done_callback(self._main_exit) > + > + @coroutine > + def _main(self, filter_proc, pipe_logger): > + try: > + if pipe_logger.poll() is None: > + yield pipe_logger.async_wait() > + if filter_proc is not None and > filter_proc.poll() is None: > + yield filter_proc.async_wait() > + except asyncio.CancelledError: > + if pipe_logger.poll() is None: > + pipe_logger.cancel() > + if filter_proc is not None and > filter_proc.poll() is None: > + filter_proc.cancel() > + raise > + > + 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() > + > + 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 a3bd662ae..eb812150f 100644 > --- a/man/make.conf.5 > +++ b/man/make.conf.5 > @@ -1,4 +1,4 @@ > -.TH "MAKE.CONF" "5" "May 2020" "Portage VERSION" "Portage" > +.TH "MAKE.CONF" "5" "Jun 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_CMD > +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 That's a lot of code...but I couldn't spot anything wrong, so looks good
