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>

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)