From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from lists.gentoo.org (pigeon.gentoo.org [208.92.234.80]) by finch.gentoo.org (Postfix) with ESMTP id 7F51713888F for ; Fri, 9 Oct 2015 16:31:30 +0000 (UTC) Received: from pigeon.gentoo.org (localhost [127.0.0.1]) by pigeon.gentoo.org (Postfix) with SMTP id 012C521C033; Fri, 9 Oct 2015 16:31:27 +0000 (UTC) Received: from smtp.gentoo.org (smtp.gentoo.org [140.211.166.183]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by pigeon.gentoo.org (Postfix) with ESMTPS id 7679821C033 for ; Fri, 9 Oct 2015 16:31:26 +0000 (UTC) Received: from professor-x (S010634bdfa9ecf80.vc.shawcable.net [96.49.31.57]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) (Authenticated sender: dolsen) by smtp.gentoo.org (Postfix) with ESMTPSA id B0AEC34070A for ; Fri, 9 Oct 2015 16:31:23 +0000 (UTC) Date: Fri, 9 Oct 2015 09:30:36 -0700 From: Brian Dolbec To: gentoo-catalyst@lists.gentoo.org Subject: Re: [gentoo-catalyst] [PATCH 2/3] log: new logging module to standardize catalyst output Message-ID: <20151009093036.75026bc4.dolsen@gentoo.org> In-Reply-To: <1444370248-13159-2-git-send-email-vapier@gentoo.org> References: <1444370248-13159-1-git-send-email-vapier@gentoo.org> <1444370248-13159-2-git-send-email-vapier@gentoo.org> Organization: Gentoo Precedence: bulk List-Post: List-Help: List-Unsubscribe: List-Subscribe: List-Id: Gentoo Linux mail X-BeenThere: gentoo-catalyst@lists.gentoo.org Reply-to: gentoo-catalyst@lists.gentoo.org MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit X-Archives-Salt: 46c80684-c7b8-48df-a1b1-cd01767432ee X-Archives-Hash: e24dcd7d8f4a23ec2201e6eba3402ab1 On Fri, 9 Oct 2015 01:57:27 -0400 Mike Frysinger 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