zmake: Improve logging

Add new flag --log-label to be the inverse of --no-log-label.
Set defaults to --log-level=INFO --no-log-label, but if --log-level is
set by the user, then default to --log-label. So a bare zmake command
will output at INFO with no labels, but zmake -l INFO will include
labels.

Suppress the job names [/mnt/.../hayato:ro] from the log lines if
--no-log-label.

Don't remove leading whitespace from logged lines, it messes up the
memory usage table.

Wait for file descriptors to stop writing output before checking for
warnings and errors in the output.

Change "Output file '...' created" to be at DEBUG instead of INFO.

BUG=None
TEST=zmake w/ no flags, -l ERROR, --log-label, --no-log-label
BRANCH=None

Change-Id: I76567ab49d5d9019c5f25c618fe10816fb2cfd35
Signed-off-by: Jeremy Bettis <jbettis@google.com>
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform/ec/+/3153592
Tested-by: Jeremy Bettis <jbettis@chromium.org>
Reviewed-by: Jack Rosenthal <jrosenth@chromium.org>
Commit-Queue: Jeremy Bettis <jbettis@chromium.org>

3 files changed, 54 insertions, 15 deletions

diff --git a/zephyr/zmake/zmake/__main__.py b/zephyr/zmake/zmake/__main__.py
index a50ca3b08d..31f0436b5a 100644
--- a/zephyr/zmake/zmake/__main__.py
+++ b/zephyr/zmake/zmake/__main__.py
@@ -133,14 +133,22 @@ def main(argv=None):
         "--log-level",
         choices=list(log_level_map.keys()),
         dest="log_level",
-        help="Set the logging level (default=WARNING)",
+        help="Set the logging level (default=INFO)",
     )
     parser.add_argument(
         "-L",
         "--no-log-label",
-        action="store_true",
-        default=False,
+        action="store_false",
         help="Turn off logging labels",
+        dest="log_label",
+        default=None,
+    )
+    parser.add_argument(
+        "--log-label",
+        action="store_true",
+        help="Turn on logging labels",
+        dest="log_label",
+        default=None,
     )
     parser.add_argument(
         "--modules-dir",
@@ -228,16 +236,25 @@ def main(argv=None):
 
     opts = parser.parse_args(argv)
 
-    if opts.no_log_label:
-        log_format = "%(message)s"
-    else:
-        log_format = "%(levelname)s: %(message)s"
+    # Default logging
+    log_level = logging.INFO
+    log_label = False
 
-    log_level = logging.WARNING
     if opts.log_level:
         log_level = log_level_map[opts.log_level]
+        log_label = True
     elif opts.debug:
         log_level = logging.DEBUG
+        log_label = True
+
+    if opts.log_label is not None:
+        log_label = opts.log_label
+    if log_label:
+        log_format = "%(levelname)s: %(message)s"
+    else:
+        log_format = "%(message)s"
+        multiproc.log_job_names = False
+
     logging.basicConfig(format=log_format, level=log_level)
 
     if not opts.debug:
diff --git a/zephyr/zmake/zmake/multiproc.py b/zephyr/zmake/zmake/multiproc.py
index 492f3b09e8..5e98374c8c 100644
--- a/zephyr/zmake/zmake/multiproc.py
+++ b/zephyr/zmake/zmake/multiproc.py
@@ -22,6 +22,8 @@ _logging_interrupt_pipe = os.pipe()
 _logging_cv = threading.Condition()
 # A map of file descriptors to their LogWriter
 _logging_map = {}
+# Should we log job names or not
+log_job_names = True
 
 
 def reset():
@@ -47,15 +49,19 @@ class LogWriter:
             key: log_level
             value: True if output was written at that level
         _job_id: The name to prepend to logged lines
+        _file_descriptor: The file descriptor being logged.
     """
 
-    def __init__(self, logger, log_level, log_level_override_func, job_id):
+    def __init__(
+        self, logger, log_level, log_level_override_func, job_id, file_descriptor
+    ):
         self._logger = logger
         self._log_level = log_level
         self._override_func = log_level_override_func
         # A map whether output was printed at each logging level
         self._written_at_level = collections.defaultdict(lambda: False)
         self._job_id = job_id
+        self._file_descriptor = file_descriptor
 
     def log_line(self, line):
         """Log a line of output
@@ -73,7 +79,7 @@ class LogWriter:
             # greatly simplifies the logic that is needed to update the log
             # level.
             self._log_level = self._override_func(line, self._log_level)
-        if self._job_id:
+        if self._job_id and log_job_names:
             self._logger.log(self._log_level, "[%s]%s", self._job_id, line)
         else:
             self._logger.log(self._log_level, line)
@@ -90,6 +96,14 @@ class LogWriter:
         """
         return self._written_at_level[log_level]
 
+    def wait(self):
+        """Wait for this LogWriter to finish.
+
+        This method will block execution until all the logs have been flushed out.
+        """
+        with _logging_cv:
+            _logging_cv.wait_for(lambda: self._file_descriptor not in _logging_map)
+
 
 def _log_fd(fd):
     """Log information from a single file descriptor.
@@ -113,7 +127,7 @@ def _log_fd(fd):
             del _logging_map[fd]
             _logging_cv.notify_all()
             return
-        line = line.strip()
+        line = line.rstrip("\n")
         if line:
             writer.log_line(line)
 
@@ -190,7 +204,9 @@ def log_output(
             _logging_thread = threading.Thread(target=_logging_loop, daemon=True)
             _logging_thread.start()
 
-        writer = LogWriter(logger, log_level, log_level_override_func, job_id)
+        writer = LogWriter(
+            logger, log_level, log_level_override_func, job_id, file_descriptor
+        )
         _logging_map[file_descriptor] = writer
         # Write a dummy byte to the pipe to break the select so we can add the
         # new fd.
diff --git a/zephyr/zmake/zmake/zmake.py b/zephyr/zmake/zmake/zmake.py
index 60d001ffc6..1b60e66f66 100644
--- a/zephyr/zmake/zmake/zmake.py
+++ b/zephyr/zmake/zmake/zmake.py
@@ -314,7 +314,11 @@ class Zmake:
                 log_level_override_func=cmake_log_level_override,
                 job_id=job_id,
             )
-            processes.append(proc)
+            if self._sequential:
+                if proc.wait():
+                    raise OSError(get_process_failure_msg(proc))
+            else:
+                processes.append(proc)
         for proc in processes:
             if proc.wait():
                 raise OSError(get_process_failure_msg(proc))
@@ -341,7 +345,6 @@ class Zmake:
                 True if all if OK
                 False if an error was found (so that zmake should exit)
             """
-            # Let all output be produced before exiting
             bad = None
             for proc in procs:
                 if proc.wait() and not bad:
@@ -354,6 +357,9 @@ class Zmake:
                 # since it exposes the fragmented nature of the build.
                 raise OSError(get_process_failure_msg(bad))
 
+            # Let all output be produced before exiting
+            for writer in writers:
+                writer.wait()
             if fail_on_warnings and any(
                 w.has_written(logging.WARNING) or w.has_written(logging.ERROR)
                 for w in writers
@@ -439,7 +445,7 @@ class Zmake:
             packer_work_dir, self.jobserver, version_string=version_string, **dirs
         ):
             shutil.copy2(output_file, output_dir / output_name)
-            self.logger.info("Output file '%r' created.", output_file)
+            self.logger.debug("Output file '%s' created.", output_file)
             output_files_out.append(output_file)
 
         return 0