diff options
author | Yuval Peress <peress@chromium.org> | 2021-01-12 12:57:05 -0700 |
---|---|---|
committer | Commit Bot <commit-bot@chromium.org> | 2021-01-14 06:17:59 +0000 |
commit | 4291b9c59ea5f8e974b7db238d69bebd2d4bb6f5 (patch) | |
tree | 310699a331ff16553012f23eefaaa7b3b3f8fd6f | |
parent | c4ad6ccf5d64e1af3abbaba257781ff02ee2a7ef (diff) | |
download | chrome-ec-4291b9c59ea5f8e974b7db238d69bebd2d4bb6f5.tar.gz |
zmake: allow overriding default log level for file descriptor
This change allows users of the multiproc logging functionality
to override the log level used for a given file descriptor.
This is particularly useful when addressing an issue with ninja
builds that print everything to stdout (including errors).
BRANCH=none
BUG=b:176364631
TEST=introduce a bug then run zmake build $BUILD_DIR, observe
most output is suppressed, but after the error takes place,
all logging is made to CRITICAL.
TEST=add unit test
Signed-off-by: Yuval Peress <peress@chromium.org>
Change-Id: I1dba8a06f0dfebe91e49829dbb8d91f1b71f58f5
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/ec/+/2625550
Reviewed-by: Jack Rosenthal <jrosenth@chromium.org>
Reviewed-by: Simon Glass <sjg@chromium.org>
-rw-r--r-- | zephyr/zmake/tests/test_multiproc_logging.py | 29 | ||||
-rw-r--r-- | zephyr/zmake/zmake/multiproc.py | 19 | ||||
-rw-r--r-- | zephyr/zmake/zmake/zmake.py | 22 |
3 files changed, 66 insertions, 4 deletions
diff --git a/zephyr/zmake/tests/test_multiproc_logging.py b/zephyr/zmake/tests/test_multiproc_logging.py index 7048319587..c53e4b3a33 100644 --- a/zephyr/zmake/tests/test_multiproc_logging.py +++ b/zephyr/zmake/tests/test_multiproc_logging.py @@ -22,6 +22,35 @@ def test_read_output_from_pipe(): logger.log.assert_called_with(logging.DEBUG, 'Hello') +def test_read_output_change_log_level(): + barrier = threading.Barrier(2) + pipe = os.pipe() + fd = io.TextIOWrapper(os.fdopen(pipe[0], 'rb'), encoding='utf-8') + logger = mock.Mock(spec=logging.Logger) + logger.log.side_effect = lambda log_lvl, line: barrier.wait() + # This call will log output from fd (the file descriptor) to DEBUG, though + # when the line starts with 'World', the logging level will be switched to + # CRITICAL (see the content of the log_lvl_override_func). + zmake.multiproc.log_output( + logger=logger, + log_level=logging.DEBUG, + file_descriptor=fd, + log_level_override_func=lambda line, lvl: + logging.CRITICAL if line.startswith('World') else lvl) + os.write(pipe[1], 'Hello\n'.encode('utf-8')) + barrier.wait() + barrier.reset() + os.write(pipe[1], 'World\n'.encode('utf-8')) + barrier.wait() + barrier.reset() + os.write(pipe[1], 'Bye\n'.encode('utf-8')) + barrier.wait() + barrier.reset() + logger.log.assert_has_calls([mock.call(logging.DEBUG, 'Hello'), + mock.call(logging.CRITICAL, 'World'), + mock.call(logging.CRITICAL, 'Bye')]) + + def test_read_output_from_second_pipe(): """Test that we can read from more than one pipe. diff --git a/zephyr/zmake/zmake/multiproc.py b/zephyr/zmake/zmake/multiproc.py index a9a8501206..a1ce853796 100644 --- a/zephyr/zmake/zmake/multiproc.py +++ b/zephyr/zmake/zmake/multiproc.py @@ -34,7 +34,7 @@ def _log_fd(fd): removed from the map as it is no longer valid. """ with _logging_cv: - logger, log_level = _logging_map[fd] + logger, log_level, log_level_override_func = _logging_map[fd] if fd.closed: del _logging_map[fd] _logging_cv.notify_all() @@ -47,6 +47,14 @@ def _log_fd(fd): return line = line.strip() if line: + if log_level_override_func: + # Get the new log level and update the default. The reason we + # want to update the default is that if we hit an error, all + # future logging should be moved to the new logging level. This + # greatly simplifies the logic that is needed to update the log + # level. + log_level = log_level_override_func(line, log_level) + _logging_map[fd] = (logger, log_level, log_level_override_func) logger.log(log_level, line) @@ -99,18 +107,23 @@ def _logging_loop(): _logging_thread = threading.Thread(target=_logging_loop, daemon=True) -def log_output(logger, log_level, file_descriptor): +def log_output(logger, log_level, file_descriptor, + log_level_override_func=None): """Log the output from the given file descriptor. Args: logger: The logger object to use. log_level: The logging level to use. file_descriptor: The file descriptor to read from. + log_level_override_func: A function used to override the log level. The + function will be called once per line prior to logging and will be + passed the arguments of the line and the default log level. """ with _logging_cv: if not _logging_thread.is_alive(): _logging_thread.start() - _logging_map[file_descriptor] = (logger, log_level) + _logging_map[file_descriptor] = (logger, log_level, + log_level_override_func) # Write a dummy byte to the pipe to break the select so we can add the # new fd. os.write(_logging_interrupt_pipe[1], b'x') diff --git a/zephyr/zmake/zmake/zmake.py b/zephyr/zmake/zmake/zmake.py index 0e4be5b5a6..653962040d 100644 --- a/zephyr/zmake/zmake/zmake.py +++ b/zephyr/zmake/zmake/zmake.py @@ -19,6 +19,22 @@ import zmake.toolchains as toolchains import zmake.util as util +def ninja_log_level_override(line, default_log_level): + """Update the log level for ninja builds if we hit an error. + + Ninja builds print everything to stdout, but really we want to start + logging things to CRITICAL + + Args: + line: The line that is about to be logged. + default_log_level: The default logging level that will be used for the + line. + """ + if line.startswith("FAILED: "): + return logging.CRITICAL + return default_log_level + + class Zmake: """Wrapper class encapsulating zmake's supported operations.""" def __init__(self, checkout=None, jobserver=None, jobs=0): @@ -156,7 +172,11 @@ class Zmake: stderr=subprocess.PIPE, encoding='utf-8', errors='replace') - zmake.multiproc.log_output(self.logger, logging.DEBUG, proc.stdout) + zmake.multiproc.log_output( + logger=self.logger, + log_level=logging.DEBUG, + file_descriptor=proc.stdout, + log_level_override_func=ninja_log_level_override) zmake.multiproc.log_output(self.logger, logging.ERROR, proc.stderr) procs.append(proc) |