[meta-oe][PATCH 0/3] Log colorizer

[meta-oe][PATCH 0/3] Log colorizer

[Chris Laplante]

This patch series turns on color compiler diagnostics. It is especially
useful when doing edit-compile-test development work with devtool.

It is based on one I've been using internally for about a
year now.

Limitation: Note that the *.nocolor and *.color logs will only contain the
 output of the task itself, not any prefuncs or postfuncs. This is
 because the color filtering is implemented using progress handlers,
 which don't see prefunc or postfunc output.

Chris Laplante (3):
  lib/oe/log_colorizer.py: add LogColorizerProxyProgressHandler
  base.bbclass: make oe.log_colorizer available in global context
  log-colorizer.bbclass: add new class

 meta/classes/base.bbclass          |  2 +-
 meta/classes/log-colorizer.bbclass | 49 +++++++++++++++++
 meta/lib/oe/log_colorizer.py       | 86 ++++++++++++++++++++++++++++++
 3 files changed, 136 insertions(+), 1 deletion(-)
 create mode 100644 meta/classes/log-colorizer.bbclass
 create mode 100644 meta/lib/oe/log_colorizer.py

--
2.17.1

[meta-oe][PATCH 1/3] lib/oe/log_colorizer.py: add LogColorizerProxyProgressHandler

[Chris Laplante]

This progress handler intercepts log output, stripping any ANSII color
escape codes. Then the stripped output is fed to the underlying progress
handler which will render the progress bar as usual.

Signed-off-by: Chris Laplante <chris.laplante@agilent.com>
---
 meta/lib/oe/log_colorizer.py | 86 ++++++++++++++++++++++++++++++++++++
 1 file changed, 86 insertions(+)
 create mode 100644 meta/lib/oe/log_colorizer.py

diff --git a/meta/lib/oe/log_colorizer.py b/meta/lib/oe/log_colorizer.py
new file mode 100644
index 0000000000..10021ef880
--- /dev/null
+++ b/meta/lib/oe/log_colorizer.py
@@ -0,0 +1,86 @@
+# Copyright (C) 2020  Agilent Technologies, Inc.
+# Author: Chris Laplante <chris.laplante@agilent.com>
+#
+# Released under the MIT license (see COPYING.MIT)
+
+from bb.progress import ProgressHandler
+from bb.build import create_progress_handler
+import contextlib
+import re
+import os.path
+
+# from https://stackoverflow.com/a/14693789/221061
+ansi_escape = re.compile(r'\x1B\[[0-?]*[ -/]*[@-~]')
+
+
+class LogColorizerProxyProgressHandler(ProgressHandler):
+    """
+    This is a proxy progress handler. It intercepts log output, stripping any
+    ANSII color escape codes. Then the stripped output is fed to the task's
+    original progress handler which will render the progress bar as usual.
+    """
+    def __init__(self, d, outfile=None, otherargs=None):
+        self._task = d.getVar("BB_RUNTASK")
+        self._color_log = None
+        self._nocolor_log = None
+        self._exit_stack = None
+        self._original_ph = None
+
+        self._suppress_color_output = not not d.getVar("LOG_COLORIZER_SUPPRESS_COLORIZED_OUTPUT")
+
+        self._tempdir = d.getVar("T")
+        logfmt = (d.getVar('BB_LOGFMT') or 'log.{task}.{pid}')
+        self._logbasename = logfmt.format(task=self._task, pid=os.getpid())
+
+        # Setup courtesy symlinks
+        for suffix in [".nocolor", ".color"]:
+            loglink = os.path.join(self._tempdir, 'log.{0}{1}'.format(self._task, suffix))
+            logfn = os.path.join(self._tempdir, self._logbasename + suffix)
+            if loglink:
+                bb.utils.remove(loglink)
+
+                try:
+                    os.symlink(self._logbasename + suffix, loglink)
+                except OSError:
+                    pass
+
+        super().__init__(d, outfile)
+
+    def __enter__(self):
+        with contextlib.ExitStack() as es:
+            self._color_log = es.enter_context(open(os.path.join(self._tempdir, self._logbasename) + ".color", "w"))
+            self._nocolor_log = es.enter_context(open(os.path.join(self._tempdir, self._logbasename) + ".nocolor", "w"))
+
+            # Reconstitute the original progress handler. We will feed stripped output to it so
+            # that the progress bar still shows up for the task.
+            original_ph = self._data.getVarFlag(self._task, "originalprogress")
+            if original_ph:
+                # We don't want task output showing up on the screen twice, so we'll just have
+                # the original progress handler write to /dev/null.
+                # Note the progress handler itself is responsible for closing the devnull handler.
+                devnull = open("/dev/null", "w")
+                self._original_ph = es.enter_context(create_progress_handler(self._task, original_ph, devnull, self._data))
+
+            self._exit_stack = es.pop_all()
+        super().__enter__()
+
+    def __exit__(self, *exc_info):
+        if self._exit_stack:
+            self._exit_stack.__exit__(*exc_info)
+        super().__exit__(*exc_info)
+
+    def write(self, string):
+        # Filter out ANSI escape sequences using the regular expression
+        filtered = ansi_escape.sub('', string)
+
+        if self._color_log:
+            self._color_log.write(string)
+
+        if self._nocolor_log:
+            self._nocolor_log.write(filtered)
+
+        if self._original_ph:
+            # Pass-through to the original progress handler so we get our progress bar
+            self._original_ph.write(filtered)
+
+        super().write(filtered if self._suppress_color_output else string)
--
2.17.1

[meta-oe][PATCH 2/3] base.bbclass: make oe.log_colorizer available in global context

[Chris Laplante]

Signed-off-by: Chris Laplante <chris.laplante@agilent.com>
---
 meta/classes/base.bbclass | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/meta/classes/base.bbclass b/meta/classes/base.bbclass
index 4c681cc870..5a969b207a 100644
--- a/meta/classes/base.bbclass
+++ b/meta/classes/base.bbclass
@@ -12,7 +12,7 @@ inherit logging

 OE_EXTRA_IMPORTS ?= ""

-OE_IMPORTS += "os sys time oe.path oe.utils oe.types oe.package oe.packagegroup oe.sstatesig oe.lsb oe.cachedpath oe.license ${OE_EXTRA_IMPORTS}"
+OE_IMPORTS += "os sys time oe.path oe.utils oe.types oe.package oe.packagegroup oe.sstatesig oe.lsb oe.cachedpath oe.license oe.log_colorizer ${OE_EXTRA_IMPORTS}"
 OE_IMPORTS[type] = "list"

 PACKAGECONFIG_CONFARGS ??= ""
--
2.17.1

[meta-oe][PATCH 3/3] log-colorizer.bbclass: add new class

[Chris Laplante]

This bbclass turns on compiler color diagnostics to make it easier to
visually interpret compiler errors and warnings. It can be used
per-recipe or globally (via INHERIT in local.conf).

You can set the LOG_COLORIZER_SUPPRESS_COLORIZED_OUTPUT variable to turn
off color output - this is intended for usage in a CI environment.

log.do_compile and log.do_configure task logs will contain the colorized
output. Non-colorized versions (log.do_<task>.nocolor) and explicitly
colorized versions (log.do_<task>.color) are created as well, regardless
of LOG_COLORIZER_SUPPRESS_COLORIZED_OUTPUT.

Signed-off-by: Chris Laplante <chris.laplante@agilent.com>
---
 meta/classes/log-colorizer.bbclass | 49 ++++++++++++++++++++++++++++++
 1 file changed, 49 insertions(+)
 create mode 100644 meta/classes/log-colorizer.bbclass

diff --git a/meta/classes/log-colorizer.bbclass b/meta/classes/log-colorizer.bbclass
new file mode 100644
index 0000000000..4271957e28
--- /dev/null
+++ b/meta/classes/log-colorizer.bbclass
@@ -0,0 +1,49 @@
+# Copyright (C) 2020  Agilent Technologies, Inc.
+# Author: Chris Laplante <chris.laplante@agilent.com>
+#
+# Released under the MIT license (see COPYING.MIT)
+
+LOG_COLORIZER_SUPPRESS_COLORIZED_OUTPUT ?= ""
+LOG_COLORIZER_SUPPRESS_COLORIZED_OUTPUT[doc] = "If set, then console output from the colorized tasks will be stripped of ANSI escape codes."
+
+LOG_COLORIZER_TASKS ?= " \
+    configure \
+    compile \
+"
+
+BB_SIGNATURE_EXCLUDE_FLAGS += "originalprogress"
+
+CFLAGS += "-fdiagnostics-color"
+
+python log_colorizer_eventhandler() {
+    def is_task_enabled(task):
+        return task in (d.getVar("__BBTASKS") or []) and "noexec" not in d.getVarFlags(task)
+
+    for task in set((d.getVar("LOG_COLORIZER_TASKS") or "").split()):
+        if not task.startswith("do_"):
+            task = "do_{0}".format(task)
+
+        if not is_task_enabled(task):
+            continue
+
+        ph = d.getVarFlag(task, "progress")
+        if ph:
+            # Stash away the original progress handler
+            d.setVarFlag(task, "originalprogress", ph)
+
+        d.setVarFlag(task, "progress", "custom:oe.log_colorizer.LogColorizerProxyProgressHandler")
+}
+
+addhandler log_colorizer_eventhandler
+log_colorizer_eventhandler[eventmask] = " \
+    bb.event.RecipeTaskPreProcess \
+"
+
+python __anonymous() {
+    if bb.data.inherits_class("cmake", d):
+        # Inject environment variable to ensure CMake/Ninja gives colorized output
+        func = d.getVar("cmake_do_compile", False)
+        if "export CLICOLOR_FORCE=1" not in [line.strip() for line in func.split("\n")]:
+            func = "\texport CLICOLOR_FORCE=1\n" + func
+            d.setVar("cmake_do_compile", func)
+}
--
2.17.1

✗ patchtest: failure for Log colorizer

[Patchwork]

== Series Details ==

Series: Log colorizer
Revision: 1
URL   : https://patchwork.openembedded.org/series/25352/
State : failure

== Summary ==


Thank you for submitting this patch series to OpenEmbedded Core. This is
an automated response. Several tests have been executed on the proposed
series by patchtest resulting in the following failures:



* Issue             Errors in your Python code were encountered [test_pylint] 
  Suggested fix    Correct the lines introduced by your patch
  Output           Please, fix the listed issues:
                   meta/lib/oe/log_colorizer.py does not exist



If you believe any of these test results are incorrect, please reply to the
mailing list (openembedded-core@lists.openembedded.org) raising your concerns.
Otherwise we would appreciate you correcting the issues and submitting a new
version of the patchset if applicable. Please ensure you add/increment the
version number when sending the new version (i.e. [PATCH] -> [PATCH v2] ->
[PATCH v3] -> ...).

---
Guidelines:     https://www.openembedded.org/wiki/Commit_Patch_Message_Guidelines
Test framework: http://git.yoctoproject.org/cgit/cgit.cgi/patchtest
Test suite:     http://git.yoctoproject.org/cgit/cgit.cgi/patchtest-oe

Re: [OE-core] [meta-oe][PATCH 0/3] Log colorizer

[Richard Purdie]

On Mon, 2020-07-27 at 21:35 -0400, Chris Laplante via lists.openembedded.org wrote:
> This patch series turns on color compiler diagnostics. It is especially
> useful when doing edit-compile-test development work with devtool.
> 
> It is based on one I've been using internally for about a
> year now.
> 
> Limitation: Note that the *.nocolor and *.color logs will only contain the
>  output of the task itself, not any prefuncs or postfuncs. This is
>  because the color filtering is implemented using progress handlers,
>  which don't see prefunc or postfunc output.
> 
> Chris Laplante (3):
>   lib/oe/log_colorizer.py: add LogColorizerProxyProgressHandler
>   base.bbclass: make oe.log_colorizer available in global context
>   log-colorizer.bbclass: add new class
> 
>  meta/classes/base.bbclass          |  2 +-
>  meta/classes/log-colorizer.bbclass | 49 +++++++++++++++++
>  meta/lib/oe/log_colorizer.py       | 86 ++++++++++++++++++++++++++++++
>  3 files changed, 136 insertions(+), 1 deletion(-)
>  create mode 100644 meta/classes/log-colorizer.bbclass
>  create mode 100644 meta/lib/oe/log_colorizer.py

This looks interesting. Could we add something to the manual about how
to use it and maybe a test for it as well please?

I did write something similar in a different context recently which
applies here near enough as well:

"""
By documentation, I mean that kernel-fitimage.bbclass has no
information in the reference manual:

https://www.yoctoproject.org/docs/latest/ref-manual/ref-manual.html#ref-classes-kernel-fitimage

generated from:
http://git.yoctoproject.org/cgit.cgi/yocto-docs/tree/documentation/ref-manual/ref-classes.xml

and also there is also no header at the start of the class saying what
it does or how to use it.

Could we add something to these locations to give more information
about the class?

For testing, have a look at
meta/lib/oeqa/selftest/cases/imagefeatures.py. Its testing target image
rootfs settings but I believe the concept is similar to how you'd test
something like the kernel-fitimage class.

You can run these tests individually with "oe-selftest -r
imagefeatures" to run that file or "oe-selftest -r
imagefeatures.ImageFeatures.test_bmap" as an example of a specific
test.
"""

although there may be a different selftest which would be a better
example to base a test off for this code.

Cheers,

Richard

Re: [OE-core] [meta-oe][PATCH 0/3] Log colorizer

[Chris Laplante]

Hi Richard,

> This looks interesting. Could we add something to the manual about how to
> use it and maybe a test for it as well please?
> 
> I did write something similar in a different context recently which applies
> here near enough as well:
> 
> """
> By documentation, I mean that kernel-fitimage.bbclass has no information in
> the reference manual:
> 
> https://www.yoctoproject.org/docs/latest/ref-manual/ref-manual.html#ref-
> classes-kernel-fitimage
> 
> generated from:
> http://git.yoctoproject.org/cgit.cgi/yocto-docs/tree/documentation/ref-
> manual/ref-classes.xml
> 
> and also there is also no header at the start of the class saying what it does
> or how to use it.
> 
> Could we add something to these locations to give more information about
> the class?
> 
> For testing, have a look at
> meta/lib/oeqa/selftest/cases/imagefeatures.py. Its testing target image
> rootfs settings but I believe the concept is similar to how you'd test
> something like the kernel-fitimage class.
> 
> You can run these tests individually with "oe-selftest -r imagefeatures" to run
> that file or "oe-selftest -r imagefeatures.ImageFeatures.test_bmap" as an
> example of a specific test.
> """
> 
> although there may be a different selftest which would be a better example
> to base a test off for this code.

Yes certainly, I'll work on them and submit a v2.  

Thanks,
Chris

Re: [OE-core] [meta-oe][PATCH 0/3] Log colorizer

[Chris Laplante]

Hi Richard,

> You can run these tests individually with "oe-selftest -r imagefeatures" to run
> that file or "oe-selftest -r imagefeatures.ImageFeatures.test_bmap" as an
> example of a specific test.

I'm developing the tests for log colorizer and I had a question about oe-selftest. Is there a way to re-run the tests without having to delete the build-st directory and start from scratch? It would save me time.  

$ oe-selftest -r log_colorizer.LogColorizerTests.test_log_colorizer_basic 
2020-07-29 10:26:55,619 - oe-selftest - INFO - Adding layer libraries:
2020-07-29 10:26:55,620 - oe-selftest - INFO - 	/home/laplante/repos/oe-core/meta/lib
2020-07-29 10:26:55,620 - oe-selftest - INFO - 	/home/laplante/repos/oe-core/meta-selftest/lib
2020-07-29 10:26:55,620 - oe-selftest - INFO - Running bitbake -e to test the configuration is valid/parsable
2020-07-29 10:26:57,190 - oe-selftest - ERROR - Build directory /home/laplante/repos/oe-core/build-st already exists, aborting

Thanks,
Chris 

Re: [OE-core] [meta-oe][PATCH 0/3] Log colorizer

[Chris Laplante]

Hi Richard,

> This looks interesting. Could we add something to the manual about how to
> use it and maybe a test for it as well please?


Halfway through writing the tests, and I realized LOG_COLORIZER_SUPPRESS_COLORIZED_OUTPUT doesn’t quite work. I wrote a test recipe with a do_compile that purposely fails with a compile error, to check whether color diagnostics work.

But I'm getting color text printed out after "Log data follows: " which is knotty's response to the bb.build.TaskFailed. 

This is because of some code of _exec_task in build.py. 


581         try:
582             for func in (prefuncs or '').split():
583                 exec_func(func, localdata)
584             exec_func(task, localdata)
585             for func in (postfuncs or '').split():
586                 exec_func(func, localdata)
587         except bb.BBHandledException:
588             event.fire(TaskFailed(task, fn, logfn, localdata, True), localdata)
589             return 1
590         except Exception as exc:
591             if quieterr:
592                 event.fire(TaskFailedSilent(task, fn, logfn, localdata), localdata)
593             else:
594                 errprinted = errchk.triggered
595                 logger.error(str(exc))
596                 event.fire(TaskFailed(task, fn, logfn, localdata, errprinted), localdata)
597             return 1


The color output is coming from line 595. The CommandFailed exception from bb.process.run carries with it the stdout of the process, which in this case has color text. 

I think at this point, I question whether I should just integrate with bit BitBake bake directly. If I were to do that, I could also fix the limitation of .color and .nocolor logs not having output from pre/postfuncs. I propose this:

log-colorizer.bbclass:
	1. Responsible for setting up CFLAGS
	2. Responsible for passing the appropriate flags/environment variables depending on build system in use (for example, the little bit of code I have targeting CMake).

BitBake:
	1. Ensure progress handlers only see filtered output. At the BitBake level I can just do this directly and not mess around with proxy progress handlers.
	2. Create a "--suppress-color" flag that filters out ANSI escape sequences from the console and the task log 
	3. Maintain the .nocolor and .color versions of the logs. Though I'm not sure how I'd keep LOG_COLORIZER_TASKS-like functionality (which only writes .nocolor/.color logs for tasks we actually expect to produce color output). Maybe I should do it automatically based on whether any escape sequences are detected.

The user would still be responsible for INHERIT'ing log-colorizer globally or per-recipe. 

What do you think?

Thanks,
Chris