Gentoo Archives: gentoo-portage-dev

From: Zac Medico <zmedico@g.o>
To: gentoo-portage-dev@l.g.o
Cc: Zac Medico <zmedico@g.o>
Subject: [gentoo-portage-dev] [PATCH] Support PORTAGE_LOG_FILTER_FILE_CMD (bug 709746)
Date: Sun, 14 Jun 2020 01:02:50
Message-Id: 20200614005744.8120-1-zmedico@gentoo.org
1 This variable specifies a command that filters build log output to a
2 log file. The plan is to extend this to support a separate filter for
3 tty output in the future.
4
5 In order to enable the EbuildPhase class to write elog messages to
6 the build log with PORTAGE_LOG_FILTER_FILE_CMD support, convert its
7 _elog method to a coroutine, and add a SchedulerInterface async_output
8 method for it to use.
9
10 Use a new BuildLogger class to manage log output (with or without a
11 filter command), with compression support provided by PipeLogger.
12 BuildLogger has a stdin property which provides access to a writable
13 binary file stream (refers to a pipe) that log content is written to.
14
15 Bug: https://bugs.gentoo.org/709746
16 Signed-off-by: Zac Medico <zmedico@g.o>
17 ---
18 lib/_emerge/AbstractEbuildProcess.py | 2 +
19 lib/_emerge/EbuildPhase.py | 47 ++++++--
20 lib/_emerge/SpawnProcess.py | 56 ++++++---
21 .../ebuild/_config/special_env_vars.py | 8 +-
22 lib/portage/util/_async/BuildLogger.py | 109 ++++++++++++++++++
23 lib/portage/util/_async/SchedulerInterface.py | 32 ++++-
24 man/make.conf.5 | 7 +-
25 7 files changed, 236 insertions(+), 25 deletions(-)
26 create mode 100644 lib/portage/util/_async/BuildLogger.py
27
28 diff --git a/lib/_emerge/AbstractEbuildProcess.py b/lib/_emerge/AbstractEbuildProcess.py
29 index 1c1955cfe..5fd4e3a1e 100644
30 --- a/lib/_emerge/AbstractEbuildProcess.py
31 +++ b/lib/_emerge/AbstractEbuildProcess.py
32 @@ -196,6 +196,8 @@ class AbstractEbuildProcess(SpawnProcess):
33 null_fd = os.open('/dev/null', os.O_RDONLY)
34 self.fd_pipes[0] = null_fd
35
36 + self.log_filter_file = self.settings.get('PORTAGE_LOG_FILTER_FILE_CMD')
37 +
38 try:
39 SpawnProcess._start(self)
40 finally:
41 diff --git a/lib/_emerge/EbuildPhase.py b/lib/_emerge/EbuildPhase.py
42 index 477e0ba97..ddb3dc719 100644
43 --- a/lib/_emerge/EbuildPhase.py
44 +++ b/lib/_emerge/EbuildPhase.py
45 @@ -26,6 +26,8 @@ from portage.package.ebuild.prepare_build_dirs import (_prepare_workdir,
46 from portage.util.futures.compat_coroutine import coroutine
47 from portage.util import writemsg
48 from portage.util._async.AsyncTaskFuture import AsyncTaskFuture
49 +from portage.util._async.BuildLogger import BuildLogger
50 +from portage.util.futures import asyncio
51 from portage.util.futures.executor.fork import ForkExecutor
52
53 try:
54 @@ -69,6 +71,11 @@ class EbuildPhase(CompositeTask):
55 _locked_phases = ("setup", "preinst", "postinst", "prerm", "postrm")
56
57 def _start(self):
58 + future = asyncio.ensure_future(self._async_start(), loop=self.scheduler)
59 + self._start_task(AsyncTaskFuture(future=future), self._async_start_exit)
60 +
61 + @coroutine
62 + def _async_start(self):
63
64 need_builddir = self.phase not in EbuildProcess._phases_without_builddir
65
66 @@ -126,7 +133,7 @@ class EbuildPhase(CompositeTask):
67 # Force background=True for this header since it's intended
68 # for the log and it doesn't necessarily need to be visible
69 # elsewhere.
70 - self._elog('einfo', msg, background=True)
71 + yield self._elog('einfo', msg, background=True)
72
73 if self.phase == 'package':
74 if 'PORTAGE_BINPKG_TMPFILE' not in self.settings:
75 @@ -134,6 +141,12 @@ class EbuildPhase(CompositeTask):
76 os.path.join(self.settings['PKGDIR'],
77 self.settings['CATEGORY'], self.settings['PF']) + '.tbz2'
78
79 + def _async_start_exit(self, task):
80 + task.future.cancelled() or task.future.result()
81 + if self._default_exit(task) != os.EX_OK:
82 + self.wait()
83 + return
84 +
85 if self.phase in ("pretend", "prerm"):
86 env_extractor = BinpkgEnvExtractor(background=self.background,
87 scheduler=self.scheduler, settings=self.settings)
88 @@ -391,6 +404,7 @@ class EbuildPhase(CompositeTask):
89 self.returncode = 1
90 self.wait()
91
92 + @coroutine
93 def _elog(self, elog_funcname, lines, background=None):
94 if background is None:
95 background = self.background
96 @@ -407,11 +421,30 @@ class EbuildPhase(CompositeTask):
97 portage.output.havecolor = global_havecolor
98 msg = out.getvalue()
99 if msg:
100 - log_path = None
101 - if self.settings.get("PORTAGE_BACKGROUND") != "subprocess":
102 - log_path = self.settings.get("PORTAGE_LOG_FILE")
103 - self.scheduler.output(msg, log_path=log_path,
104 - background=background)
105 + build_logger = None
106 + try:
107 + log_file = None
108 + log_path = None
109 + if self.settings.get("PORTAGE_BACKGROUND") != "subprocess":
110 + log_path = self.settings.get("PORTAGE_LOG_FILE")
111 + if log_path:
112 + build_logger = BuildLogger(env=self.settings.environ(),
113 + log_path=log_path,
114 + log_filter_file=self.settings.get('PORTAGE_LOG_FILTER_FILE_CMD'),
115 + scheduler=self.scheduler)
116 + build_logger.start()
117 + log_file = build_logger.stdin
118 +
119 + yield self.scheduler.async_output(msg, log_file=log_file,
120 + background=background)
121 +
122 + if build_logger is not None:
123 + build_logger.stdin.close()
124 + yield build_logger.async_wait()
125 + except asyncio.CancelledError:
126 + if build_logger is not None:
127 + build_logger.cancel()
128 + raise
129
130
131 class _PostPhaseCommands(CompositeTask):
132 @@ -480,4 +513,4 @@ class _PostPhaseCommands(CompositeTask):
133 qa_msg.extend("\t%s: %s" % (filename, " ".join(sorted(soname_deps)))
134 for filename, soname_deps in unresolved)
135 qa_msg.append("")
136 - self.elog("eqawarn", qa_msg)
137 + yield self.elog("eqawarn", qa_msg)
138 diff --git a/lib/_emerge/SpawnProcess.py b/lib/_emerge/SpawnProcess.py
139 index 395d66bb9..160ff023b 100644
140 --- a/lib/_emerge/SpawnProcess.py
141 +++ b/lib/_emerge/SpawnProcess.py
142 @@ -19,7 +19,10 @@ from portage.const import BASH_BINARY
143 from portage.localization import _
144 from portage.output import EOutput
145 from portage.util import writemsg_level
146 +from portage.util._async.BuildLogger import BuildLogger
147 from portage.util._async.PipeLogger import PipeLogger
148 +from portage.util.futures import asyncio
149 +from portage.util.futures.compat_coroutine import coroutine
150
151 class SpawnProcess(SubProcess):
152
153 @@ -34,8 +37,8 @@ class SpawnProcess(SubProcess):
154 "path_lookup", "pre_exec", "close_fds", "cgroup",
155 "unshare_ipc", "unshare_mount", "unshare_pid", "unshare_net")
156
157 - __slots__ = ("args",) + \
158 - _spawn_kwarg_names + ("_pipe_logger", "_selinux_type",)
159 + __slots__ = ("args", "log_filter_file") + \
160 + _spawn_kwarg_names + ("_main_task", "_selinux_type",)
161
162 # Max number of attempts to kill the processes listed in cgroup.procs,
163 # given that processes may fork before they can be killed.
164 @@ -137,13 +140,43 @@ class SpawnProcess(SubProcess):
165 fcntl.fcntl(stdout_fd,
166 fcntl.F_GETFD) | fcntl.FD_CLOEXEC)
167
168 - self._pipe_logger = PipeLogger(background=self.background,
169 + build_logger = BuildLogger(env=self.env,
170 + log_path=log_file_path,
171 + log_filter_file=self.log_filter_file,
172 + scheduler=self.scheduler)
173 + build_logger.start()
174 +
175 + pipe_logger = PipeLogger(background=self.background,
176 scheduler=self.scheduler, input_fd=master_fd,
177 - log_file_path=log_file_path,
178 + log_file_path=build_logger.stdin,
179 stdout_fd=stdout_fd)
180 - self._pipe_logger.addExitListener(self._pipe_logger_exit)
181 - self._pipe_logger.start()
182 +
183 + pipe_logger.start()
184 +
185 self._registered = True
186 + self._main_task = asyncio.ensure_future(self._main(build_logger, pipe_logger), loop=self.scheduler)
187 + self._main_task.add_done_callback(self._main_exit)
188 +
189 + @coroutine
190 + def _main(self, build_logger, pipe_logger):
191 + try:
192 + if pipe_logger.poll() is None:
193 + yield pipe_logger.async_wait()
194 + if build_logger.poll() is None:
195 + yield build_logger.async_wait()
196 + except asyncio.CancelledError:
197 + if pipe_logger.poll() is None:
198 + pipe_logger.cancel()
199 + if build_logger.poll() is None:
200 + build_logger.cancel()
201 + raise
202 +
203 + def _main_exit(self, main_task):
204 + try:
205 + main_task.result()
206 + except asyncio.CancelledError:
207 + self.cancel()
208 + self._async_waitpid()
209
210 def _can_log(self, slave_fd):
211 return True
212 @@ -167,20 +200,17 @@ class SpawnProcess(SubProcess):
213
214 return spawn_func(args, **kwargs)
215
216 - def _pipe_logger_exit(self, pipe_logger):
217 - self._pipe_logger = None
218 - self._async_waitpid()
219 -
220 def _unregister(self):
221 SubProcess._unregister(self)
222 if self.cgroup is not None:
223 self._cgroup_cleanup()
224 self.cgroup = None
225 - if self._pipe_logger is not None:
226 - self._pipe_logger.cancel()
227 - self._pipe_logger = None
228 + if self._main_task is not None:
229 + self._main_task.done() or self._main_task.cancel()
230
231 def _cancel(self):
232 + if self._main_task is not None:
233 + self._main_task.done() or self._main_task.cancel()
234 SubProcess._cancel(self)
235 self._cgroup_cleanup()
236
237 diff --git a/lib/portage/package/ebuild/_config/special_env_vars.py b/lib/portage/package/ebuild/_config/special_env_vars.py
238 index 440dd00b2..f44cb9b1b 100644
239 --- a/lib/portage/package/ebuild/_config/special_env_vars.py
240 +++ b/lib/portage/package/ebuild/_config/special_env_vars.py
241 @@ -1,4 +1,4 @@
242 -# Copyright 2010-2019 Gentoo Authors
243 +# Copyright 2010-2020 Gentoo Authors
244 # Distributed under the terms of the GNU General Public License v2
245
246 from __future__ import unicode_literals
247 @@ -175,7 +175,7 @@ environ_filter += [
248 "PORTAGE_RO_DISTDIRS",
249 "PORTAGE_RSYNC_EXTRA_OPTS", "PORTAGE_RSYNC_OPTS",
250 "PORTAGE_RSYNC_RETRIES", "PORTAGE_SSH_OPTS", "PORTAGE_SYNC_STALE",
251 - "PORTAGE_USE",
252 + "PORTAGE_USE", "PORTAGE_LOG_FILTER_FILE_CMD",
253 "PORTAGE_LOGDIR", "PORTAGE_LOGDIR_CLEAN",
254 "QUICKPKG_DEFAULT_OPTS", "REPOMAN_DEFAULT_OPTS",
255 "RESUMECOMMAND", "RESUMECOMMAND_FTP",
256 @@ -204,7 +204,9 @@ default_globals = {
257 'PORTAGE_BZIP2_COMMAND': 'bzip2',
258 }
259
260 -validate_commands = ('PORTAGE_BZIP2_COMMAND', 'PORTAGE_BUNZIP2_COMMAND',)
261 +validate_commands = ('PORTAGE_BZIP2_COMMAND', 'PORTAGE_BUNZIP2_COMMAND',
262 + 'PORTAGE_LOG_FILTER_FILE_CMD',
263 +)
264
265 # To enhance usability, make some vars case insensitive
266 # by forcing them to lower case.
267 diff --git a/lib/portage/util/_async/BuildLogger.py b/lib/portage/util/_async/BuildLogger.py
268 new file mode 100644
269 index 000000000..f5fea77ea
270 --- /dev/null
271 +++ b/lib/portage/util/_async/BuildLogger.py
272 @@ -0,0 +1,109 @@
273 +# Copyright 2020 Gentoo Authors
274 +# Distributed under the terms of the GNU General Public License v2
275 +
276 +import subprocess
277 +
278 +from portage import os
279 +from portage.util import shlex_split
280 +from _emerge.AsynchronousTask import AsynchronousTask
281 +from portage.util._async.PipeLogger import PipeLogger
282 +from portage.util._async.PopenProcess import PopenProcess
283 +from portage.util.futures import asyncio
284 +from portage.util.futures.compat_coroutine import coroutine
285 +
286 +
287 +class BuildLogger(AsynchronousTask):
288 + """
289 + Write to a log file, with compression support provided by PipeLogger.
290 + If the log_filter_file parameter is specified, then it is interpreted
291 + as a command to execute which filters log output (see the
292 + PORTAGE_LOG_FILTER_FILE_CMD variable in make.conf(5)). The stdin property
293 + provides access to a writable binary file stream (refers to a pipe)
294 + that log content should be written to (usually redirected from
295 + subprocess stdout and stderr streams).
296 + """
297 +
298 + __slots__ = ('env', 'log_path', 'log_filter_file', '_main_task', '_stdin')
299 +
300 + @property
301 + def stdin(self):
302 + return self._stdin
303 +
304 + def _start(self):
305 + filter_proc = None
306 + log_input = None
307 + if self.log_path is not None:
308 + log_filter_file = self.log_filter_file
309 + if log_filter_file is not None:
310 + split_value = shlex_split(log_filter_file)
311 + log_filter_file = split_value if split_value else None
312 + if log_filter_file:
313 + filter_input, stdin = os.pipe()
314 + log_input, filter_output = os.pipe()
315 + try:
316 + filter_proc = PopenProcess(
317 + proc=subprocess.Popen(
318 + log_filter_file,
319 + env=self.env,
320 + stdin=filter_input,
321 + stdout=filter_output,
322 + stderr=filter_output,
323 + ),
324 + scheduler=self.scheduler,
325 + )
326 + filter_proc.start()
327 + except EnvironmentError:
328 + # Maybe the command is missing or broken somehow...
329 + os.close(filter_input)
330 + os.close(stdin)
331 + os.close(log_input)
332 + os.close(filter_output)
333 + else:
334 + self._stdin = os.fdopen(stdin, 'wb', 0)
335 + os.close(filter_input)
336 + os.close(filter_output)
337 +
338 + if self._stdin is None:
339 + # Since log_filter_file is unspecified or refers to a file
340 + # that is missing or broken somehow, create a pipe that
341 + # logs directly to pipe_logger.
342 + log_input, stdin = os.pipe()
343 + self._stdin = os.fdopen(stdin, 'wb', 0)
344 +
345 + # Set background=True so that pipe_logger does not log to stdout.
346 + pipe_logger = PipeLogger(background=True,
347 + scheduler=self.scheduler, input_fd=log_input,
348 + log_file_path=self.log_path)
349 + pipe_logger.start()
350 +
351 + self._main_task = asyncio.ensure_future(self._main(filter_proc, pipe_logger), loop=self.scheduler)
352 + self._main_task.add_done_callback(self._main_exit)
353 +
354 + @coroutine
355 + def _main(self, filter_proc, pipe_logger):
356 + try:
357 + if pipe_logger.poll() is None:
358 + yield pipe_logger.async_wait()
359 + if filter_proc is not None and filter_proc.poll() is None:
360 + yield filter_proc.async_wait()
361 + except asyncio.CancelledError:
362 + if pipe_logger.poll() is None:
363 + pipe_logger.cancel()
364 + if filter_proc is not None and filter_proc.poll() is None:
365 + filter_proc.cancel()
366 + raise
367 +
368 + def _cancel(self):
369 + if self._main_task is not None:
370 + self._main_task.done() or self._main_task.cancel()
371 + if self._stdin is not None and not self._stdin.closed:
372 + self._stdin.close()
373 +
374 + def _main_exit(self, main_task):
375 + try:
376 + main_task.result()
377 + except asyncio.CancelledError:
378 + self.cancel()
379 + self._was_cancelled()
380 + self.returncode = self.returncode or 0
381 + self._async_wait()
382 diff --git a/lib/portage/util/_async/SchedulerInterface.py b/lib/portage/util/_async/SchedulerInterface.py
383 index ec6417da1..3ff250d1d 100644
384 --- a/lib/portage/util/_async/SchedulerInterface.py
385 +++ b/lib/portage/util/_async/SchedulerInterface.py
386 @@ -1,4 +1,4 @@
387 -# Copyright 2012-2018 Gentoo Foundation
388 +# Copyright 2012-2020 Gentoo Authors
389 # Distributed under the terms of the GNU General Public License v2
390
391 import gzip
392 @@ -7,6 +7,8 @@ import errno
393 from portage import _encodings
394 from portage import _unicode_encode
395 from portage.util import writemsg_level
396 +from portage.util.futures._asyncio.streams import _writer
397 +from portage.util.futures.compat_coroutine import coroutine
398 from ..SlotObject import SlotObject
399
400 class SchedulerInterface(SlotObject):
401 @@ -53,6 +55,34 @@ class SchedulerInterface(SlotObject):
402 def _return_false():
403 return False
404
405 + @coroutine
406 + def async_output(self, msg, log_file=None, background=None,
407 + level=0, noiselevel=-1):
408 + """
409 + Output a msg to stdio (if not in background) and to a log file
410 + if provided.
411 +
412 + @param msg: a message string, including newline if appropriate
413 + @type msg: str
414 + @param log_file: log file in binary mode
415 + @type log_file: file
416 + @param background: send messages only to log (not to stdio)
417 + @type background: bool
418 + @param level: a numeric logging level (see the logging module)
419 + @type level: int
420 + @param noiselevel: passed directly to writemsg
421 + @type noiselevel: int
422 + """
423 + global_background = self._is_background()
424 + if background is None or global_background:
425 + background = global_background
426 +
427 + if not background:
428 + writemsg_level(msg, level=level, noiselevel=noiselevel)
429 +
430 + if log_file is not None:
431 + yield _writer(log_file, _unicode_encode(msg))
432 +
433 def output(self, msg, log_path=None, background=None,
434 level=0, noiselevel=-1):
435 """
436 diff --git a/man/make.conf.5 b/man/make.conf.5
437 index a3bd662ae..eb812150f 100644
438 --- a/man/make.conf.5
439 +++ b/man/make.conf.5
440 @@ -1,4 +1,4 @@
441 -.TH "MAKE.CONF" "5" "May 2020" "Portage VERSION" "Portage"
442 +.TH "MAKE.CONF" "5" "Jun 2020" "Portage VERSION" "Portage"
443 .SH "NAME"
444 make.conf \- custom settings for Portage
445 .SH "SYNOPSIS"
446 @@ -979,6 +979,11 @@ with an integer pid. For example, a value of "ionice \-c 3 \-p \\${PID}"
447 will set idle io priority. For more information about ionice, see
448 \fBionice\fR(1). This variable is unset by default.
449 .TP
450 +.B PORTAGE_LOG_FILTER_FILE_CMD
451 +This variable specifies a command that filters build log output to a
452 +log file. In order to filter ANSI escape codes from build logs,
453 +\fBansifilter\fR(1) is a convenient setting for this variable.
454 +.TP
455 .B PORTAGE_LOGDIR
456 This variable defines the directory in which per\-ebuild logs are kept.
457 Logs are created only when this is set. They are stored as
458 --
459 2.25.3