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          |   2 +
 lib/_emerge/EbuildPhase.py                    |  47 ++++++--
 lib/_emerge/SpawnProcess.py                   |  56 ++++++---
 .../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 +-
 7 files changed, 236 insertions(+), 25 deletions(-)
 create mode 100644 lib/portage/util/_async/BuildLogger.py

diff --git a/lib/_emerge/AbstractEbuildProcess.py 
b/lib/_emerge/AbstractEbuildProcess.py
index 1c1955cfe..5fd4e3a1e 100644
--- a/lib/_emerge/AbstractEbuildProcess.py
+++ b/lib/_emerge/AbstractEbuildProcess.py
@@ -196,6 +196,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_CMD')
+
                try:
                        SpawnProcess._start(self)
                finally:
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..160ff023b 100644
--- a/lib/_emerge/SpawnProcess.py
+++ b/lib/_emerge/SpawnProcess.py
@@ -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/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
-- 
2.25.3


Reply via email to