From 7ee93b206a6389e6eb7b9440dc2fae801c77bc9b Mon Sep 17 00:00:00 2001 From: Richard Purdie Date: Fri, 12 Aug 2011 23:24:43 +0100 Subject: bitbake/logging: Overhaul internal logging process At the moment it bugs me a lot that we only have one effective logging level for bitbake, despite the logging module having provision to do more advanced things. This patch: * Changes the core log level to the lowest level we have messages of (DEBUG-2) so messages always flow through the core logger * Allows build.py's task logging code to log all the output regardless of what output is on the console and sets this so log files now always contain debug level messages even if these don't appear on the console * Moves the verbose/debug/debug-domains code to be a UI side setting * Adds a filter to the UI to only print the user requested output. The result is more complete logfiles on disk but the usual output to the console. There are some behaviour changes intentionally made by this patch: a) the -v option now controls whether output is tee'd to the console. Ultimately, we likely want to output a message to the user about where the log file is and avoid placing output directly onto the console for every executing task. b) The functions get_debug_levels, the debug_levels variable, the set_debug_levels, the set_verbosity and set_debug_domains functions are removed from bb.msg. c) The "logging" init function changes format. d) All messages get fired to all handlers all the time leading to an increase in inter-process traffic. This could likely be hacked around short term with a function for a UI to only request events greater than level X. Longer term, having masks for event handlers would be better. e) logger.getEffectiveLevel() is no longer a reliable guide to what will/won't get logged so for now we look at the default log levels instead. [YOCTO #304] (Bitbake rev: 45aad2f9647df14bcfa5e755b57e1ddab377939a) Signed-off-by: Richard Purdie --- bitbake/bin/bitbake | 3 +- bitbake/bin/bitdoc | 5 ++- bitbake/lib/bb/__init__.py | 2 +- bitbake/lib/bb/build.py | 6 ++-- bitbake/lib/bb/msg.py | 74 +++++++++++++++++++++++++++------------------ bitbake/lib/bb/ui/knotty.py | 5 +-- bitbake/lib/bb/utils.py | 15 --------- 7 files changed, 57 insertions(+), 53 deletions(-) (limited to 'bitbake') diff --git a/bitbake/bin/bitbake b/bitbake/bin/bitbake index fdeeb36a40..56f39f8efe 100755 --- a/bitbake/bin/bitbake +++ b/bitbake/bin/bitbake @@ -190,7 +190,7 @@ Default BBFILES are the .bb files in the current directory.""") # server is daemonized this logfile will be truncated. cooker_logfile = os.path.join(os.getcwd(), "cooker.log") - bb.utils.init_logger(bb.msg, configuration.verbose, configuration.debug, + bb.msg.init_msgconfig(configuration.verbose, configuration.debug, configuration.debug_domains) # Ensure logging messages get sent to the UI as events @@ -228,6 +228,7 @@ Default BBFILES are the .bb files in the current directory.""") try: return server.launchUI(ui_main, server_connection.connection, server_connection.events) finally: + bb.event.ui_queue = [] server_connection.terminate() return 1 diff --git a/bitbake/bin/bitdoc b/bitbake/bin/bitdoc index 98fb025a50..08a0173d72 100755 --- a/bitbake/bin/bitdoc +++ b/bitbake/bin/bitdoc @@ -430,9 +430,8 @@ Create a set of html pages (documentation) for a bitbake.conf.... action = "store_true", dest = "verbose", default = False ) options, args = parser.parse_args( sys.argv ) - - if options.debug: - bb.msg.set_debug_level(options.debug) + + bb.msg.init_msgconfig(options.verbose, options.debug) return options.config, options.output diff --git a/bitbake/lib/bb/__init__.py b/bitbake/lib/bb/__init__.py index 06d865994c..3c8572476c 100644 --- a/bitbake/lib/bb/__init__.py +++ b/bitbake/lib/bb/__init__.py @@ -56,7 +56,7 @@ logging.setLoggerClass(BBLogger) logger = logging.getLogger("BitBake") logger.addHandler(NullHandler()) -logger.setLevel(logging.INFO) +logger.setLevel(logging.DEBUG - 2) # This has to be imported after the setLoggerClass, as the import of bb.msg # can result in construction of the various loggers. diff --git a/bitbake/lib/bb/build.py b/bitbake/lib/bb/build.py index 5c703095b7..31fde06e6a 100644 --- a/bitbake/lib/bb/build.py +++ b/bitbake/lib/bb/build.py @@ -223,7 +223,7 @@ def exec_func_shell(function, d, runfile, cwd=None): with open(runfile, 'w') as script: script.write('#!/bin/sh -e\n') - if logger.isEnabledFor(logging.DEBUG): + if bb.msg.loggerVerbose[1]: script.write("set -x\n") data.emit_func(function, script, d) if cwd: @@ -234,7 +234,7 @@ def exec_func_shell(function, d, runfile, cwd=None): cmd = runfile - if logger.isEnabledFor(logging.DEBUG): + if bb.msg.loggerVerbose[1]: logfile = LogTee(logger, sys.stdout) else: logfile = sys.stdout @@ -308,6 +308,8 @@ def _exec_task(fn, task, d, quieterr): # Ensure python logging goes to the logfile handler = logging.StreamHandler(logfile) handler.setFormatter(logformatter) + # Always enable full debug output into task logfiles + handler.setLevel(logging.DEBUG - 2) bblogger.addHandler(handler) localdata.setVar('BB_LOGFILE', logfn) diff --git a/bitbake/lib/bb/msg.py b/bitbake/lib/bb/msg.py index 12d19ff8e1..77a7a0fed2 100644 --- a/bitbake/lib/bb/msg.py +++ b/bitbake/lib/bb/msg.py @@ -75,6 +75,25 @@ class BBLogFormatter(logging.Formatter): msg += '\n' + ''.join(formatted) return msg +class BBLogFilter(object): + def __init__(self, handler, level, debug_domains): + self.stdlevel = level + self.debug_domains = debug_domains + loglevel = level + for domain in debug_domains: + if debug_domains[domain] < loglevel: + loglevel = debug_domains[domain] + handler.setLevel(loglevel) + handler.addFilter(self) + + def filter(self, record): + if record.levelno >= self.stdlevel: + return True + if record.name in self.debug_domains and record.levelno >= self.debug_domains[record.name]: + return True + return False + + class Loggers(dict): def __getitem__(self, key): if key in self: @@ -84,12 +103,6 @@ class Loggers(dict): dict.__setitem__(self, key, log) return log -class DebugLevel(dict): - def __getitem__(self, key): - if key == "default": - key = domain.Default - return get_debug_level(key) - def _NamedTuple(name, fields): Tuple = collections.namedtuple(name, " ".join(fields)) return Tuple(*range(len(fields))) @@ -110,44 +123,47 @@ domain = _NamedTuple("Domain", ( "Util")) logger = logging.getLogger("BitBake") loggers = Loggers() -debug_level = DebugLevel() # Message control functions # -def set_debug_level(level): - for log in loggers.itervalues(): - log.setLevel(logging.NOTSET) +loggerDefaultDebugLevel = 0 +loggerDefaultVerbose = False +loggerDefaultDomains = [] - if level: - logger.setLevel(logging.DEBUG - level + 1) - else: - logger.setLevel(logging.INFO) +def init_msgconfig(verbose, debug, debug_domains = []): + """ + Set default verbosity and debug levels config the logger + """ + bb.msg.loggerDebugLevel = debug + bb.msg.loggerVerbose = verbose + bb.msg.loggerDefaultDomains = debug_domains -def get_debug_level(msgdomain = domain.Default): - if not msgdomain: - level = logger.getEffectiveLevel() - else: - level = loggers[msgdomain].getEffectiveLevel() - return max(0, logging.DEBUG - level + 1) +def addDefaultlogFilter(handler): -def set_verbose(level): - if level: - logger.setLevel(BBLogFormatter.VERBOSE) + debug = loggerDefaultDebugLevel + verbose = loggerDefaultVerbose + domains = loggerDefaultDomains + + if debug: + level = BBLogFormatter.DEBUG - debug + 1 + elif verbose: + level = BBLogFormatter.VERBOSE else: - logger.setLevel(BBLogFormatter.INFO) + level = BBLogFormatter.NOTE -def set_debug_domains(domainargs): - for (domainarg, iterator) in groupby(domainargs): + debug_domains = {} + for (domainarg, iterator) in groupby(domains): + dlevel = len(tuple(iterator)) + debug_domains["BitBake.%s" % domainarg] = logging.DEBUG - dlevel + 1 for index, msgdomain in enumerate(domain._fields): if msgdomain == domainarg: - level = len(tuple(iterator)) - if level: - loggers[index].setLevel(logging.DEBUG - level + 1) break else: warn(None, "Logging domain %s is not valid, ignoring" % domainarg) + BBLogFilter(handler, level, debug_domains) + # # Message handling functions # diff --git a/bitbake/lib/bb/ui/knotty.py b/bitbake/lib/bb/ui/knotty.py index 7a2681d2bf..7c645adcc4 100644 --- a/bitbake/lib/bb/ui/knotty.py +++ b/bitbake/lib/bb/ui/knotty.py @@ -74,6 +74,7 @@ def main(server, eventHandler): console = logging.StreamHandler(sys.stdout) format = bb.msg.BBLogFormatter("%(levelname)s: %(message)s") + bb.msg.addDefaultlogFilter(console) console.setFormatter(format) logger.addHandler(console) @@ -120,8 +121,8 @@ def main(server, eventHandler): # For "normal" logging conditions, don't show note logs from tasks # but do show them if the user has changed the default log level to # include verbose/debug messages - if logger.getEffectiveLevel() > format.VERBOSE: - if event.taskpid != 0 and event.levelno <= format.NOTE: + #if logger.getEffectiveLevel() > format.VERBOSE: + if event.taskpid != 0 and event.levelno <= format.NOTE: continue logger.handle(event) continue diff --git a/bitbake/lib/bb/utils.py b/bitbake/lib/bb/utils.py index 4eac2852ed..1cf1a8da44 100644 --- a/bitbake/lib/bb/utils.py +++ b/bitbake/lib/bb/utils.py @@ -830,21 +830,6 @@ def which(path, item, direction = 0): return "" -def init_logger(logger, verbose, debug, debug_domains): - """ - Set verbosity and debug levels in the logger - """ - - if debug: - bb.msg.set_debug_level(debug) - elif verbose: - bb.msg.set_verbose(True) - else: - bb.msg.set_debug_level(0) - - if debug_domains: - bb.msg.set_debug_domains(debug_domains) - def to_boolean(string, default=None): if not string: return default -- cgit v1.2.3-54-g00ecf