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

[Mike Frysinger]

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
-- 
2.5.2