[PATCH 0/4] More Bitbake logging improvements

[PATCH 0/4] More Bitbake logging improvements

[Joshua Watt]

Supplemental patches to improve logging in bitbake by using python
structured logging. Fixes up some ResourceWarnings and improves the
flexibility of the console and consolelog.


Joshua Watt (4):
  bitbake: knotty: Add logging cleanup
  bitbake: msg: Add helper to merge logging configs
  bitbake: knotty: Update hash equivalence logging
  bitbake: runqueue: Lower setscene complete logging level

 bitbake/contrib/autobuilderlog.json |  18 +----
 bitbake/lib/bb/msg.py               | 100 ++++++++++++++++------------
 bitbake/lib/bb/runqueue.py          |   2 +-
 bitbake/lib/bb/ui/knotty.py         |  70 ++++++++++++++++---
 4 files changed, 124 insertions(+), 66 deletions(-)

-- 
2.17.1

[PATCH 1/4] bitbake: knotty: Add logging cleanup

[Joshua Watt]

Adds code to close all loggers when bitbake exits. This prevents
unclosed file ResourceWarnings. A form of this closing existed
previously, but was removed in the new logging code.

Signed-off-by: Joshua Watt <JPEWhacker@gmail.com>
---
 bitbake/lib/bb/msg.py       | 11 +++++++++++
 bitbake/lib/bb/ui/knotty.py |  2 ++
 2 files changed, 13 insertions(+)

diff --git a/bitbake/lib/bb/msg.py b/bitbake/lib/bb/msg.py
index ced605d96d..ee3c38b5a4 100644
--- a/bitbake/lib/bb/msg.py
+++ b/bitbake/lib/bb/msg.py
@@ -284,3 +284,14 @@ def setLoggingConfig(defaultconfig, userconfigfile=None):
         # TODO: I don't think that setting the global log level should be necessary
         #if newlevel < bb.msg.loggerDefaultLogLevel:
         #    bb.msg.loggerDefaultLogLevel = newlevel
+
+def cleanupLogging():
+    # Iterate through all the handlers and close them if possible. Fixes
+    # 'Unclosed resource' warnings when bitbake exits, see
+    # https://bugs.python.org/issue23010
+    handlers = set()
+    for logger_iter in logging.Logger.manager.loggerDict.keys():
+        handlers.update(logging.getLogger(logger_iter).handlers)
+
+    for h in handlers:
+        h.close()
diff --git a/bitbake/lib/bb/ui/knotty.py b/bitbake/lib/bb/ui/knotty.py
index b229687ef8..2dfce90a4f 100644
--- a/bitbake/lib/bb/ui/knotty.py
+++ b/bitbake/lib/bb/ui/knotty.py
@@ -823,4 +823,6 @@ def main(server, eventHandler, params, tf = TerminalFilter):
         if e.errno == errno.EPIPE:
             pass
 
+    bb.msg.cleanupLogging()
+
     return return_value
-- 
2.17.1

[PATCH 2/4] bitbake: msg: Add helper to merge logging configs

[Joshua Watt]

Adds a function that can be used by UI front ends to merge logging
configuration fragments.

Signed-off-by: Joshua Watt <JPEWhacker@gmail.com>
---
 bitbake/lib/bb/msg.py | 89 +++++++++++++++++++++++--------------------
 1 file changed, 48 insertions(+), 41 deletions(-)

diff --git a/bitbake/lib/bb/msg.py b/bitbake/lib/bb/msg.py
index ee3c38b5a4..c22d0d3e15 100644
--- a/bitbake/lib/bb/msg.py
+++ b/bitbake/lib/bb/msg.py
@@ -193,6 +193,53 @@ def has_console_handler(logger):
                 return True
     return False
 
+def mergeLoggingConfig(logconfig, userconfig):
+    logconfig = copy.deepcopy(logconfig)
+    userconfig = copy.deepcopy(userconfig)
+
+    # Merge config with the default config
+    if userconfig.get('version') != logconfig['version']:
+        raise BaseException("Bad user configuration version. Expected %r, got %r" % (logconfig['version'], userconfig.get('version')))
+
+    # Set some defaults to make merging easier
+    userconfig.setdefault("loggers", {})
+
+    # If a handler, formatter, or filter is defined in the user
+    # config, it will replace an existing one in the default config
+    for k in ("handlers", "formatters", "filters"):
+        logconfig.setdefault(k, {}).update(userconfig.get(k, {}))
+
+    seen_loggers = set()
+    for name, l in logconfig["loggers"].items():
+        # If the merge option is set, merge the handlers and
+        # filters. Otherwise, if it is False, this logger won't get
+        # add to the set of seen loggers and will replace the
+        # existing one
+        if l.get('bitbake_merge', True):
+            ulogger = userconfig["loggers"].setdefault(name, {})
+            ulogger.setdefault("handlers", [])
+            ulogger.setdefault("filters", [])
+
+            # Merge lists
+            l.setdefault("handlers", []).extend(ulogger["handlers"])
+            l.setdefault("filters", []).extend(ulogger["filters"])
+
+            # Replace other properties if present
+            if "level" in ulogger:
+                l["level"] = ulogger["level"]
+
+            if "propagate" in ulogger:
+                l["propagate"] = ulogger["propagate"]
+
+            seen_loggers.add(name)
+
+    # Add all loggers present in the user config, but not any that
+    # have already been processed
+    for name in set(userconfig["loggers"].keys()) - seen_loggers:
+        logconfig["loggers"][name] = userconfig["loggers"][name]
+
+    return logconfig
+
 def setLoggingConfig(defaultconfig, userconfigfile=None):
     logconfig = copy.deepcopy(defaultconfig)
 
@@ -208,47 +255,7 @@ def setLoggingConfig(defaultconfig, userconfigfile=None):
                 raise BaseException("Unrecognized file format: %s" % userconfigfile)
 
             if userconfig.get('bitbake_merge', True):
-                # Merge config with the default config
-                if userconfig.get('version') != logconfig['version']:
-                    raise BaseException("Bad user configuration version. Expected %r, got %r" % (logconfig['version'], userconfig.get('version')))
-
-                # Set some defaults to make merging easier
-                userconfig.setdefault("loggers", {})
-
-                # If a handler, formatter, or filter is defined in the user
-                # config, it will replace an existing one in the default config
-                for k in ("handlers", "formatters", "filters"):
-                    logconfig.setdefault(k, {}).update(userconfig.get(k, {}))
-
-                seen_loggers = set()
-                for name, l in logconfig["loggers"].items():
-                    # If the merge option is set, merge the handlers and
-                    # filters. Otherwise, if it is False, this logger won't get
-                    # add to the set of seen loggers and will replace the
-                    # existing one
-                    if l.get('bitbake_merge', True):
-                        ulogger = userconfig["loggers"].setdefault(name, {})
-                        ulogger.setdefault("handlers", [])
-                        ulogger.setdefault("filters", [])
-
-                        # Merge lists
-                        l.setdefault("handlers", []).extend(ulogger["handlers"])
-                        l.setdefault("filters", []).extend(ulogger["filters"])
-
-                        # Replace other properties if present
-                        if "level" in ulogger:
-                            l["level"] = ulogger["level"]
-
-                        if "propagate" in ulogger:
-                            l["propagate"] = ulogger["propagate"]
-
-                        seen_loggers.add(name)
-
-                # Add all loggers present in the user config, but not any that
-                # have already been processed
-                for name in set(userconfig["loggers"].keys()) - seen_loggers:
-                    logconfig["loggers"][name] = userconfig["loggers"][name]
-
+                logconfig = mergeLoggingConfig(logconfig, userconfig)
             else:
                 # Replace the entire default config
                 logconfig = userconfig
-- 
2.17.1

[PATCH 3/4] bitbake: knotty: Update hash equivalence logging

[Joshua Watt]

Updates hash equivalence logging so that the interesting VERBOSE
messages are always logged to the consolelog file so that issues in
individual user builds can be diagnosed. The autobuilder logging config
then updates this so that they also are shown on stdout, since the
consolelog file is not capture there.

In order to facilitate this, 2 new logging handlers were added,
"BitBake.verbconsole" and "BitBake.verbconsolelog". Neither of these
handlers are attached to anything by default, but they will log any
messages that wouldn't otherwise be logged by the normal console or
consolelog handlers. Users can attach whatever loggers the desire to
this handler to get them to appear on the console or in the consolelog,
as demonstrated by the autobuilderlog.json file.

Signed-off-by: Joshua Watt <JPEWhacker@gmail.com>
---
 bitbake/contrib/autobuilderlog.json | 18 +-------
 bitbake/lib/bb/ui/knotty.py         | 68 +++++++++++++++++++++++++----
 2 files changed, 62 insertions(+), 24 deletions(-)

diff --git a/bitbake/contrib/autobuilderlog.json b/bitbake/contrib/autobuilderlog.json
index 103a1141f6..193a675a1f 100644
--- a/bitbake/contrib/autobuilderlog.json
+++ b/bitbake/contrib/autobuilderlog.json
@@ -1,27 +1,13 @@
 {
     "version": 1,
-    "handlers": {
-        "autobuilderlog": {
-            "class": "logging.FileHandler",
-            "formatter": "logfileFormatter",
-            "level": "DEBUG",
-            "filename": "autobuilder.log",
-            "mode": "w"
-        }
-    },
-    "formatters": {
-            "logfileFormatter": {
-                "format": "%(name)s: %(levelname)s: %(message)s"
-            }
-    },
     "loggers": {
         "BitBake.SigGen.HashEquiv": {
             "level": "VERBOSE",
-            "handlers": ["autobuilderlog"]
+            "handlers": ["BitBake.verbconsole"]
         },
         "BitBake.RunQueue.HashEquiv": {
             "level": "VERBOSE",
-            "handlers": ["autobuilderlog"]
+            "handlers": ["BitBake.verbconsole"]
         }
     }
 }
diff --git a/bitbake/lib/bb/ui/knotty.py b/bitbake/lib/bb/ui/knotty.py
index 2dfce90a4f..b4df5f6e88 100644
--- a/bitbake/lib/bb/ui/knotty.py
+++ b/bitbake/lib/bb/ui/knotty.py
@@ -419,6 +419,18 @@ def main(server, eventHandler, params, tf = TerminalFilter):
                 "stream": "ext://sys.stderr",
                 "filters": ["BitBake.stderrFilter"],
             },
+            # This handler can be used if specific loggers should print on
+            # the console at a lower severity than the default. It will
+            # display any messages sent to it that are lower than then
+            # BitBake.console logging level (so as to prevent duplication of
+            # messages). Nothing is attached to this handler by default
+            "BitBake.verbconsole": {
+                "class": "logging.StreamHandler",
+                "formatter": "BitBake.consoleFormatter",
+                "level": 1,
+                "stream": "ext://sys.stdout",
+                "filters": ["BitBake.verbconsoleFilter"],
+            },
         },
         "formatters": {
             # This format instance will get color output enabled by the
@@ -442,7 +454,11 @@ def main(server, eventHandler, params, tf = TerminalFilter):
             "BitBake.stderrFilter": {
                 "()": "bb.msg.LogFilterGEQLevel",
                 "level": "ERROR"
-            }
+            },
+            "BitBake.verbconsoleFilter": {
+                "()": "bb.msg.LogFilterLTLevel",
+                "level": console_loglevel
+            },
         },
         "loggers": {
             "BitBake": {
@@ -455,13 +471,49 @@ def main(server, eventHandler, params, tf = TerminalFilter):
 
     # Enable the console log file if enabled
     if consolelogfile and not params.options.show_environment and not params.options.show_versions:
-        logconfig["handlers"]["BitBake.consolelog"] ={
-            "class": "logging.FileHandler",
-            "formatter": "BitBake.logfileFormatter",
-            "level": "INFO",
-            "filename": consolelogfile,
-        }
-        logconfig["loggers"]["BitBake"]["handlers"].append("BitBake.consolelog")
+        logconfig = bb.msg.mergeLoggingConfig(logconfig, {
+                "version": 1,
+                "handlers" : {
+                    "BitBake.consolelog": {
+                        "class": "logging.FileHandler",
+                        "formatter": "BitBake.logfileFormatter",
+                        "level": loglevel,
+                        "filename": consolelogfile,
+                    },
+                    # Just like verbconsole, anything sent here will go to the
+                    # log file, unless it would go to BitBake.consolelog
+                    "BitBake.verbconsolelog" : {
+                        "class": "logging.FileHandler",
+                        "formatter": "BitBake.logfileFormatter",
+                        "level": 1,
+                        "filename": consolelogfile,
+                        "filters": ["BitBake.verbconsolelogFilter"],
+                    },
+                },
+                "filters": {
+                    "BitBake.verbconsolelogFilter": {
+                        "()": "bb.msg.LogFilterLTLevel",
+                        "level": loglevel,
+                    },
+                },
+                "loggers": {
+                    "BitBake": {
+                        "handlers": ["BitBake.consolelog"],
+                    },
+
+                    # Other interesting things that we want to keep an eye on
+                    # in the log files in case someone has an issue, but not
+                    # necessarily show to the user on the console
+                    "BitBake.SigGen.HashEquiv": {
+                        "level": "VERBOSE",
+                        "handlers": ["BitBake.verbconsolelog"],
+                    },
+                    "BitBake.RunQueue.HashEquiv": {
+                        "level": "VERBOSE",
+                        "handlers": ["BitBake.verbconsolelog"],
+                    }
+                }
+            })
 
         bb.utils.mkdirhier(os.path.dirname(consolelogfile))
         loglink = os.path.join(os.path.dirname(consolelogfile), 'console-latest.log')
-- 
2.17.1

[PATCH 4/4] bitbake: runqueue: Lower setscene complete logging level

[Joshua Watt]

Lowers the level of the log message when setscene tasks have completed.
This message can occur multiple times when hash equivalence is enabled,
since the runqueue switches between executing setscene tasks and normal
tasks. Since this is primarily of use when debugging hash equivalence,
use the hash equivalence logger at VERBOSE level.

[YOCTO #13813]

Signed-off-by: Joshua Watt <JPEWhacker@gmail.com>
---
 bitbake/lib/bb/runqueue.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/bitbake/lib/bb/runqueue.py b/bitbake/lib/bb/runqueue.py
index cef9b0fbbf..16f076f3b1 100644
--- a/bitbake/lib/bb/runqueue.py
+++ b/bitbake/lib/bb/runqueue.py
@@ -2059,7 +2059,7 @@ class RunQueueExecute:
         self.update_holdofftasks()
 
         if not self.sq_live and not self.sqdone and not self.sq_deferred and not self.updated_taskhash_queue and not self.holdoff_tasks:
-            logger.info("Setscene tasks completed")
+            hashequiv_logger.verbose("Setscene tasks completed")
 
             err = self.summarise_scenequeue_errors()
             if err:
-- 
2.17.1