Re: [PATCH 2/2] Support PORTAGE_LOG_FILTER_FILE_CMD (bug 709746)

On Fri, 19 Jun 2020 13:39:19 -0700
Zac Medico <[email protected]> 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 <[email protected]>
> ---
>  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