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 (bug 709746)
Date: Wed, 26 Feb 2020 08:24:21
Message-Id: 20200226082353.28885-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 support, convert its _elog
7 method to a coroutine, and add a SchedulerInterface async_output
8 method for it to use.
9
10 Bug: https://bugs.gentoo.org/709746
11 Signed-off-by: Zac Medico <zmedico@g.o>
12 ---
13 lib/_emerge/AbstractEbuildProcess.py | 2 +
14 lib/_emerge/EbuildPhase.py | 22 +++-
15 lib/_emerge/SpawnProcess.py | 33 +++++-
16 .../ebuild/_config/special_env_vars.py | 6 +-
17 lib/portage/util/_async/BuildLogger.py | 103 ++++++++++++++++++
18 lib/portage/util/_async/SchedulerInterface.py | 30 +++++
19 man/make.conf.5 | 4 +
20 7 files changed, 191 insertions(+), 9 deletions(-)
21 create mode 100644 lib/portage/util/_async/BuildLogger.py
22
23 diff --git a/lib/_emerge/AbstractEbuildProcess.py b/lib/_emerge/AbstractEbuildProcess.py
24 index d1a6d1c4e..3732f80ed 100644
25 --- a/lib/_emerge/AbstractEbuildProcess.py
26 +++ b/lib/_emerge/AbstractEbuildProcess.py
27 @@ -181,6 +181,8 @@ class AbstractEbuildProcess(SpawnProcess):
28 null_fd = os.open('/dev/null', os.O_RDONLY)
29 self.fd_pipes[0] = null_fd
30
31 + self.log_filter_file = self.settings.get('PORTAGE_LOG_FILTER_FILE')
32 +
33 try:
34 yield SpawnProcess._async_start(self)
35 finally:
36 diff --git a/lib/_emerge/EbuildPhase.py b/lib/_emerge/EbuildPhase.py
37 index 63d0746da..fd766e590 100644
38 --- a/lib/_emerge/EbuildPhase.py
39 +++ b/lib/_emerge/EbuildPhase.py
40 @@ -26,6 +26,7 @@ from portage.package.ebuild.prepare_build_dirs import (_prepare_workdir,
41 from portage.util.futures.compat_coroutine import coroutine, coroutine_return
42 from portage.util import writemsg
43 from portage.util._async.AsyncTaskFuture import AsyncTaskFuture
44 +from portage.util._async.BuildLogger import BuildLogger
45 from portage.util.futures.executor.fork import ForkExecutor
46
47 try:
48 @@ -130,7 +131,7 @@ class EbuildPhase(CompositeTask):
49 # Force background=True for this header since it's intended
50 # for the log and it doesn't necessarily need to be visible
51 # elsewhere.
52 - self._elog('einfo', msg, background=True)
53 + yield self._elog('einfo', msg, background=True)
54
55 if self.phase == 'package':
56 if 'PORTAGE_BINPKG_TMPFILE' not in self.settings:
57 @@ -392,6 +393,7 @@ class EbuildPhase(CompositeTask):
58 self.returncode = 1
59 self.wait()
60
61 + @coroutine
62 def _elog(self, elog_funcname, lines, background=None):
63 if background is None:
64 background = self.background
65 @@ -408,12 +410,26 @@ class EbuildPhase(CompositeTask):
66 portage.output.havecolor = global_havecolor
67 msg = out.getvalue()
68 if msg:
69 + build_logger = None
70 + log_file = None
71 log_path = None
72 if self.settings.get("PORTAGE_BACKGROUND") != "subprocess":
73 log_path = self.settings.get("PORTAGE_LOG_FILE")
74 - self.scheduler.output(msg, log_path=log_path,
75 + if log_path:
76 + build_logger = BuildLogger(env=self.settings.environ(),
77 + log_path=log_path,
78 + log_filter_file=self.settings.get('PORTAGE_LOG_FILTER_FILE'),
79 + scheduler=self.scheduler)
80 + yield build_logger.async_start()
81 + log_file = build_logger.stdin
82 +
83 + yield self.scheduler.async_output(msg, log_file=log_file,
84 background=background)
85
86 + if build_logger is not None:
87 + if build_logger.stdin is not None:
88 + build_logger.stdin.close()
89 + yield build_logger.async_wait()
90
91 class _PostPhaseCommands(CompositeTask):
92
93 @@ -481,4 +497,4 @@ class _PostPhaseCommands(CompositeTask):
94 qa_msg.extend("\t%s: %s" % (filename, " ".join(sorted(soname_deps)))
95 for filename, soname_deps in unresolved)
96 qa_msg.append("")
97 - self.elog("eqawarn", qa_msg)
98 + yield self.elog("eqawarn", qa_msg)
99 diff --git a/lib/_emerge/SpawnProcess.py b/lib/_emerge/SpawnProcess.py
100 index ba58d9d0e..4d96ce9ed 100644
101 --- a/lib/_emerge/SpawnProcess.py
102 +++ b/lib/_emerge/SpawnProcess.py
103 @@ -19,6 +19,7 @@ from portage.const import BASH_BINARY
104 from portage.localization import _
105 from portage.output import EOutput
106 from portage.util import writemsg_level
107 +from portage.util._async.BuildLogger import BuildLogger
108 from portage.util._async.PipeLogger import PipeLogger
109 from portage.util.futures.compat_coroutine import coroutine
110
111 @@ -35,8 +36,8 @@ class SpawnProcess(SubProcess):
112 "path_lookup", "pre_exec", "close_fds", "cgroup",
113 "unshare_ipc", "unshare_mount", "unshare_pid", "unshare_net")
114
115 - __slots__ = ("args",) + \
116 - _spawn_kwarg_names + ("_pipe_logger", "_selinux_type",)
117 + __slots__ = ("args", "log_filter_file") + \
118 + _spawn_kwarg_names + ("_build_logger", "_pipe_logger", "_selinux_type",)
119
120 # Max number of attempts to kill the processes listed in cgroup.procs,
121 # given that processes may fork before they can be killed.
122 @@ -141,9 +142,17 @@ class SpawnProcess(SubProcess):
123 fcntl.fcntl(stdout_fd,
124 fcntl.F_GETFD) | fcntl.FD_CLOEXEC)
125
126 + self._build_logger = BuildLogger(env=self.env,
127 + log_path=log_file_path,
128 + log_filter_file=self.log_filter_file,
129 + scheduler=self.scheduler)
130 +
131 + self._build_logger.addExitListener(self._build_logger_exit)
132 + yield self._build_logger.async_start()
133 +
134 self._pipe_logger = PipeLogger(background=self.background,
135 scheduler=self.scheduler, input_fd=master_fd,
136 - log_file_path=log_file_path,
137 + log_file_path=self._build_logger.stdin,
138 stdout_fd=stdout_fd)
139 self._pipe_logger.addExitListener(self._pipe_logger_exit)
140 self._registered = True
141 @@ -173,13 +182,29 @@ class SpawnProcess(SubProcess):
142
143 def _pipe_logger_exit(self, pipe_logger):
144 self._pipe_logger = None
145 - self._async_waitpid()
146 + if self._build_logger is None:
147 + self._async_waitpid()
148 +
149 + def _build_logger_exit(self, build_logger):
150 + self._build_logger = None
151 + if self._pipe_logger is None:
152 + self._async_waitpid()
153 +
154 + def _async_waitpid(self):
155 + if self._build_logger is not None:
156 + # All output should have been collected by now, so kill it.
157 + self._build_logger.cancel()
158 + SubProcess._async_waitpid(self)
159
160 def _unregister(self):
161 SubProcess._unregister(self)
162 if self.cgroup is not None:
163 self._cgroup_cleanup()
164 self.cgroup = None
165 + if self._build_logger is not None:
166 + self._build_logger.removeExitListener(self._build_logger_exit)
167 + self._build_logger.cancel()
168 + self._build_logger = None
169 if self._pipe_logger is not None:
170 self._pipe_logger.cancel()
171 self._pipe_logger = None
172 diff --git a/lib/portage/package/ebuild/_config/special_env_vars.py b/lib/portage/package/ebuild/_config/special_env_vars.py
173 index dc01339f7..977245309 100644
174 --- a/lib/portage/package/ebuild/_config/special_env_vars.py
175 +++ b/lib/portage/package/ebuild/_config/special_env_vars.py
176 @@ -175,7 +175,7 @@ environ_filter += [
177 "PORTAGE_RO_DISTDIRS",
178 "PORTAGE_RSYNC_EXTRA_OPTS", "PORTAGE_RSYNC_OPTS",
179 "PORTAGE_RSYNC_RETRIES", "PORTAGE_SSH_OPTS", "PORTAGE_SYNC_STALE",
180 - "PORTAGE_USE",
181 + "PORTAGE_USE", "PORTAGE_LOG_FILTER_FILE",
182 "PORTAGE_LOGDIR", "PORTAGE_LOGDIR_CLEAN",
183 "QUICKPKG_DEFAULT_OPTS", "REPOMAN_DEFAULT_OPTS",
184 "RESUMECOMMAND", "RESUMECOMMAND_FTP",
185 @@ -204,7 +204,9 @@ default_globals = {
186 'PORTAGE_BZIP2_COMMAND': 'bzip2',
187 }
188
189 -validate_commands = ('PORTAGE_BZIP2_COMMAND', 'PORTAGE_BUNZIP2_COMMAND',)
190 +validate_commands = ('PORTAGE_BZIP2_COMMAND', 'PORTAGE_BUNZIP2_COMMAND',
191 + 'PORTAGE_LOG_FILTER_FILE',
192 +)
193
194 # To enhance usability, make some vars case insensitive
195 # by forcing them to lower case.
196 diff --git a/lib/portage/util/_async/BuildLogger.py b/lib/portage/util/_async/BuildLogger.py
197 new file mode 100644
198 index 000000000..04da17c78
199 --- /dev/null
200 +++ b/lib/portage/util/_async/BuildLogger.py
201 @@ -0,0 +1,103 @@
202 +# Copyright 2020 Gentoo Authors
203 +# Distributed under the terms of the GNU General Public License v2
204 +
205 +import portage
206 +portage.proxy.lazyimport.lazyimport(globals(),
207 + '_emerge.SpawnProcess:SpawnProcess',
208 +)
209 +
210 +from portage import os
211 +from portage.util import shlex_split
212 +from _emerge.AsynchronousTask import AsynchronousTask
213 +from portage.util._async.PipeLogger import PipeLogger
214 +from portage.util.futures.compat_coroutine import coroutine
215 +
216 +
217 +class BuildLogger(AsynchronousTask):
218 + """
219 + Write to a log file, with compression support provided by PipeLogger.
220 + If the log_filter_file parameter is specified, then it is interpreted
221 + as a command to execute which filters log output (see the
222 + PORTAGE_LOG_FILTER_FILE variable in make.conf(5)). The stdin property
223 + provides access to a binary file object (refers to a pipe) that log
224 + content should be written to (usually redirected from subprocess
225 + stdout and stderr streams).
226 + """
227 +
228 + __slots__ = ('env', 'log_path', 'log_filter_file', '_pipe_logger', '_filter_proc', '_stdin')
229 +
230 + @property
231 + def stdin(self):
232 + return self._stdin
233 +
234 + def _start(self):
235 + self.scheduler.run_until_complete(self._async_start())
236 +
237 + @coroutine
238 + def _async_start(self):
239 + if self.log_path is not None:
240 + log_filter_file = self.log_filter_file
241 + if log_filter_file is not None:
242 + split_value = shlex_split(log_filter_file)
243 + log_filter_file = split_value if split_value else None
244 + if log_filter_file:
245 + filter_input, stdin = os.pipe()
246 + log_input, filter_output = os.pipe()
247 + self._filter_proc = SpawnProcess(
248 + args=log_filter_file,
249 + env=self.env,
250 + fd_pipes={0: filter_input, 1: filter_output, 2: filter_output},
251 + scheduler=self.scheduler)
252 + try:
253 + yield self._filter_proc.async_start()
254 + except portage.exception.CommandNotFound:
255 + self._filter_proc._unregister()
256 + self._filter_proc = None
257 + os.close(filter_input)
258 + os.close(stdin)
259 + os.close(log_input)
260 + os.close(filter_output)
261 + else:
262 + self._stdin = os.fdopen(stdin, 'wb', 0)
263 + os.close(filter_input)
264 + os.close(filter_output)
265 + # Create a PipeLogger instance to read output from
266 + # self._filter_proc and log it. Set background=True
267 + # so that this instance does not log to stdout.
268 + self._pipe_logger = PipeLogger(background=True,
269 + scheduler=self.scheduler, input_fd=log_input,
270 + log_file_path=self.log_path)
271 + yield self._pipe_logger.async_start()
272 +
273 + self._pipe_logger.async_wait().add_done_callback(self._pipe_logger_exit)
274 + self._filter_proc.async_wait().add_done_callback(self._filter_proc_exit)
275 +
276 + if self._stdin is None:
277 + # Since log_filter_file is unspecified or refers to a file that
278 + # was not found, create a pipe that logs directly to a PipeLogger
279 + # instance.
280 + log_input, stdin = os.pipe()
281 + self._stdin = os.fdopen(stdin, 'wb', 0)
282 + self._pipe_logger = PipeLogger(background=True,
283 + scheduler=self.scheduler, input_fd=log_input,
284 + log_file_path=self.log_path)
285 + yield self._pipe_logger.async_start()
286 + self._pipe_logger.async_wait().add_done_callback(self._pipe_logger_exit)
287 +
288 + def _cancel(self):
289 + if self._pipe_logger is not None and self._pipe_logger.poll() is None:
290 + self._pipe_logger.cancel()
291 + if self._filter_proc is not None and self._filter_proc.poll() is None:
292 + self._filter_proc.cancel()
293 +
294 + def _pipe_logger_exit(self, future):
295 + self._pipe_logger = None
296 + if self._filter_proc is None:
297 + self.returncode = 0
298 + self._async_wait()
299 +
300 + def _filter_proc_exit(self, future):
301 + self._filter_proc = None
302 + if self._pipe_logger is None:
303 + self.returncode = 0
304 + self._async_wait()
305 diff --git a/lib/portage/util/_async/SchedulerInterface.py b/lib/portage/util/_async/SchedulerInterface.py
306 index ec6417da1..1a9599d6f 100644
307 --- a/lib/portage/util/_async/SchedulerInterface.py
308 +++ b/lib/portage/util/_async/SchedulerInterface.py
309 @@ -7,6 +7,8 @@ import errno
310 from portage import _encodings
311 from portage import _unicode_encode
312 from portage.util import writemsg_level
313 +from portage.util.futures._asyncio.streams import _writer
314 +from portage.util.futures.compat_coroutine import coroutine
315 from ..SlotObject import SlotObject
316
317 class SchedulerInterface(SlotObject):
318 @@ -53,6 +55,34 @@ class SchedulerInterface(SlotObject):
319 def _return_false():
320 return False
321
322 + @coroutine
323 + def async_output(self, msg, log_file=None, background=None,
324 + level=0, noiselevel=-1):
325 + """
326 + Output a msg to stdio (if not in background) and to a log file
327 + if provided.
328 +
329 + @param msg: a message string, including newline if appropriate
330 + @type msg: str
331 + @param log_file: log file in binary mode
332 + @type log_file: file
333 + @param background: send messages only to log (not to stdio)
334 + @type background: bool
335 + @param level: a numeric logging level (see the logging module)
336 + @type level: int
337 + @param noiselevel: passed directly to writemsg
338 + @type noiselevel: int
339 + """
340 + global_background = self._is_background()
341 + if background is None or global_background:
342 + background = global_background
343 +
344 + if not background:
345 + writemsg_level(msg, level=level, noiselevel=noiselevel)
346 +
347 + if log_file is not None:
348 + yield _writer(log_file, _unicode_encode(msg))
349 +
350 def output(self, msg, log_path=None, background=None,
351 level=0, noiselevel=-1):
352 """
353 diff --git a/man/make.conf.5 b/man/make.conf.5
354 index f82fed65a..69bfa6cdf 100644
355 --- a/man/make.conf.5
356 +++ b/man/make.conf.5
357 @@ -979,6 +979,10 @@ with an integer pid. For example, a value of "ionice \-c 3 \-p \\${PID}"
358 will set idle io priority. For more information about ionice, see
359 \fBionice\fR(1). This variable is unset by default.
360 .TP
361 +.B PORTAGE_LOG_FILTER_FILE
362 +This variable specifies a command that filters build log output to a
363 +log file.
364 +.TP
365 .B PORTAGE_LOGDIR
366 This variable defines the directory in which per\-ebuild logs are kept.
367 Logs are created only when this is set. They are stored as
368 --
369 2.24.1

Replies