Re: [gentoo-catalyst] [PATCH 2/3] log: new logging module to standardize catalyst output

[Brian Dolbec]

On Fri,  9 Oct 2015 01:57:27 -0400
Mike Frysinger <vapier@g.o> wrote:

> This has everything you could ever want:
> - control where output is sent (stdout or a file)
> - control over log level
> - automatic exit when CRITICAL is used
> - automatic colorization of critical/error/warning messages
> - explicit control over use of colors
> - automatic handling of embedded newlines
> - standardized output format
> - all logging routed through a single logger (not the root)
> - additional log level between warning & info: notice
>
> This just lays the groundwork -- no code is actually converted over
> to using this.  That will be done in follow up commit(s).
>
> Note: The default output level has changed from "info" to "notice".
> That means the default display won't spam w/irrelevant details.
>
> Example output (only the main.py module is converted):
> $ ./bin/wrapper.py -s test
> 09 Oct 2015 01:34:56 EDT: NOTICE  : Using default Catalyst
> configuration file: /etc/catalyst/catalyst.conf ContentsMap:
> __init__(), search_order = ['pixz', 'lbzip2', 'isoinfo_l',
> 'squashfs', 'gzip', 'xz', 'bzip2', 'tar', 'isoinfo_f'] Creating
> Portage tree snapshot test from /usr/portage... ^C
>
> $ ./bin/wrapper.py -s test --debug
> 09 Oct 2015 01:35:43 EDT: INFO    : main.py:version: Catalyst git
> 09 Oct 2015 01:35:43 EDT: INFO    : main.py:version: vcs version
> 4440e8908c677d8764e29b0f127e2dd6c02b7621, date Fri Oct 9 01:28:19
> 2015 -0400 09 Oct 2015 01:35:43 EDT: INFO    : main.py:version:
> Copyright 2003-2015 Gentoo Foundation 09 Oct 2015 01:35:43 EDT:
> INFO    : main.py:version: Copyright 2008-2012 various authors 09 Oct
> 2015 01:35:43 EDT: INFO    : main.py:version: Distributed under the
> GNU General Public License version 2.1 09 Oct 2015 01:35:43 EDT:
> NOTICE  : log.py:notice: Using default Catalyst configuration
> file: /etc/catalyst/catalyst.conf 09 Oct 2015 01:35:43 EDT: INFO    :
> main.py:parse_config: Snapshot cache support enabled. 09 Oct 2015
> 01:35:43 EDT: INFO    : main.py:parse_config: Kernel cache support
> enabled. 09 Oct 2015 01:35:43 EDT: INFO    : main.py:parse_config:
> Autoresuming support enabled. 09 Oct 2015 01:35:43 EDT: INFO    :
> main.py:parse_config: Package cache support enabled. 09 Oct 2015
> 01:35:43 EDT: INFO    : main.py:parse_config: Seed cache support
> enabled. 09 Oct 2015 01:35:43 EDT: INFO    : main.py:parse_config:
> Envscript support enabled. 09 Oct 2015 01:35:43 EDT: DEBUG   :
> main.py:main: conf_values[options] = set(['snapcache', 'kerncache',
> 'autoresume', 'pkgcache', 'bindist', 'seedcache']) ^C
>
> $ ./bin/wrapper.py -s test -C /asdf
> 09 Oct 2015 01:36:59 EDT: NOTICE  : Using default Catalyst
> configuration file: /etc/catalyst/catalyst.conf ContentsMap:
> __init__(), search_order = ['pixz', 'lbzip2', 'isoinfo_l',
> 'squashfs', 'gzip', 'xz', 'bzip2', 'tar', 'isoinfo_f']
>
> !!! catalyst: Syntax error: 0
>
> 09 Oct 2015 01:36:59 EDT: CRITICAL: Could not parse commandline
> ---
>  catalyst/log.py  | 130
> +++++++++++++++++++++++++++++++++++++++++++++++++++++++
> catalyst/main.py |  30 ++++++++++++- 2 files changed, 158
> insertions(+), 2 deletions(-) create mode 100644 catalyst/log.py
>
> diff --git a/catalyst/log.py b/catalyst/log.py
> new file mode 100644
> index 0000000..bf39116
> --- /dev/null
> +++ b/catalyst/log.py
> @@ -0,0 +1,130 @@
> +# Copyright 2003-2015 Gentoo Foundation
> +# Distributed under the terms of the GNU General Public License v2
> +
> +"""Logging related code
> +
> +This largely exposes the same interface as the logging module except
> we add +another level "notice" between warning & info, and all output
> goes through +the "catalyst" logger.
> +"""
> +
> +from __future__ import print_function
> +
> +import logging
> +import logging.handlers
> +import os
> +import sys
> +import time
> +
> +
> +class CatalystLogger(logging.Logger):
> +	"""Override the _log member to autosplit on new lines"""
> +
> +	def _log(self, level, msg, args, **kwargs):
> +		"""If given a multiline message, split it"""
> +		# We have to interpolate it first in case they
> spread things out
> +		# over multiple lines like: Bad Thing:\n%s\nGoodbye!
> +		msg %= args
> +		for line in msg.splitlines():
> +			super(CatalystLogger, self)._log(level,
> line, (), **kwargs) +
> +
> +# The logger that all output should go through.
> +# This is ugly because we want to not perturb the logging module
> state. +_klass = logging.getLoggerClass()
> +logging.setLoggerClass(CatalystLogger)
> +logger = logging.getLogger('catalyst')
> +logging.setLoggerClass(_klass)
> +del _klass
> +
> +
> +# Set the notice level between warning and info.
> +NOTICE = (logging.WARNING + logging.INFO) / 2
> +logging.addLevelName(NOTICE, 'NOTICE')
> +
> +
> +# The API we expose to consumers.
> +def notice(msg, *args, **kwargs):
> +	"""Log a notice message"""
> +	logger.log(NOTICE, msg, *args, **kwargs)
> +
> +def critical(msg, *args, **kwargs):
> +	"""Log a critical message and then exit"""
> +	status = kwargs.pop('status', 1)
> +	logger.critical(msg, *args, **kwargs)
> +	sys.exit(status)
> +
> +error = logger.error
> +warning = logger.warning
> +info = logger.info
> +debug = logger.debug
> +
> +
> +class CatalystFormatter(logging.Formatter):
> +	"""Mark bad messages with colors automatically"""
> +
> +	_COLORS = {
> +		'CRITICAL':	'\033[1;35m',
> +		'ERROR':	'\033[1;31m',
> +		'WARNING':	'\033[1;33m',
> +		'DEBUG':	'\033[1;34m',
> +	}
> +	_NORMAL = '\033[0m'
> +
> +	@staticmethod
> +	def detect_color():
> +		"""Figure out whether the runtime env wants color"""
> +		if 'NOCOLOR' is os.environ:
> +			return False
> +		return os.isatty(sys.stdout.fileno())
> +
> +	def __init__(self, *args, **kwargs):
> +		"""Initialize"""
> +		color = kwargs.pop('color', None)
> +		if color is None:
> +			color = self.detect_color()
> +		if not color:
> +			self._COLORS = {}
> +
> +		super(CatalystFormatter, self).__init__(*args,
> **kwargs) +
> +	def format(self, record, **kwargs):
> +		"""Format the |record| with our color settings"""
> +		#print(dir(record))
> +		#print(record.getMessage())
> +		msg = super(CatalystFormatter, self).format(record,
> **kwargs)
> +		#print('{', msg, '}')
> +		color = self._COLORS.get(record.levelname)
> +		if color:
> +			return color + msg + self._NORMAL
> +		else:
> +			return msg
> +
> +
> +def setup_logging(level, output=None, debug=False, color=None):
> +	"""Initialize the logging module using the |level| level"""
> +	# The incoming level will be things like "info", but
> setLevel wants
> +	# the numeric constant.  Convert it here.
> +	level = logging.getLevelName(level.upper())
> +
> +	# The good stuff.
> +	fmt = '%(asctime)s: %(levelname)-8s: '
> +	if debug:
> +		fmt += '%(filename)s:%(funcName)s: '
> +	fmt += '%(message)s'
> +
> +	# Figure out where to send the log output.
> +	if output is None:
> +		handler = logging.StreamHandler(stream=sys.stdout)
> +	else:
> +		handler = logging.FileHandler(output)
> +
> +	# Use a date format that is readable by humans & machines.
> +	# Think e-mail/RFC 2822: 05 Oct 2013 18:58:50 EST
> +	tzname = time.strftime('%Z', time.localtime())
> +	datefmt = '%d %b %Y %H:%M:%S ' + tzname
> +	formatter = CatalystFormatter(fmt, datefmt, color=color)
> +	handler.setFormatter(formatter)
> +
> +	logger.addHandler(handler)
> +	logger.setLevel(level)
> diff --git a/catalyst/main.py b/catalyst/main.py
> index e6b6447..c9a2219 100644
> --- a/catalyst/main.py
> +++ b/catalyst/main.py
> @@ -18,6 +18,7 @@ from DeComp.definitions import
> (COMPRESS_DEFINITIONS, DECOMPRESS_DEFINITIONS, CONTENTS_DEFINITIONS)
>  from DeComp.contents import ContentsMap
>
> +from catalyst import log
>  import catalyst.config
>  import catalyst.util
>  from catalyst.defaults import confdefaults, option_messages
> @@ -176,10 +177,23 @@ $ catalyst -f stage1-specfile.spec"""
>  	group = parser.add_argument_group('Program output options')
>  	group.add_argument('-d', '--debug',
>  		default=False, action='store_true',
> -		help='enable debugging')
> +		help='enable debugging (and default --log-level
> debug)') group.add_argument('-v', '--verbose',
>  		default=False, action='store_true',
> -		help='verbose output')
> +		help='verbose output (and default --log-level info)')
> +	group.add_argument('--log-level',
> +		default=None,
> +		choices=('critical', 'error', 'warning', 'notice',
> 'info', 'debug'),
> +		help='set verbosity of output')
> +	group.add_argument('--log-file',
> +		type=FilePath(exists=False),
> +		help='write all output to this file (instead of
> stdout)')
> +	group.add_argument('--color',
> +		default=None, action='store_true',
> +		help='colorize output all the time (default:
> detect)')
> +	group.add_argument('--nocolor',
> +		dest='color', action='store_false',
> +		help='never colorize output all the time (default:
> detect)')
>  	group = parser.add_argument_group('Temporary file
> management') group.add_argument('-a', '--clear-autoresume',
> @@ -218,6 +232,18 @@ def main():
>  	parser = get_parser()
>  	opts = parser.parse_args(sys.argv[1:])
>
> +	# Initialize the logger before anything else.
> +	log_level = opts.log_level
> +	if log_level is None:
> +		if opts.debug:
> +			log_level = 'debug'
> +		elif opts.verbose:
> +			log_level = 'info'
> +		else:
> +			log_level = 'notice'
> +	log.setup_logging(log_level, output=opts.log_file,
> debug=opts.debug,
> +		color=opts.color)
> +
>  	# Parse the command line options.
>  	myconfig = opts.config
>  	myspecfile = opts.file

Very nice. :)   I learned a bit in here ;)

In gkeys I had it log to a file always, but didn't add color to the
console output.

-- 
Brian Dolbec <dolsen>