Merge pull request #2897 from MinchinWeb/rich-logging

Rich logging

pelican/__init__.py

@@ -13,10 +13,9 @@ from collections.abc import Iterable
 from pkgutil import extend_path
 __path__ = extend_path(__path__, __name__)
 
-from rich.console import Console
-
 # pelican.log has to be the first pelican module to be loaded
 # because logging.setLoggerClass has to be called before logging.getLogger
+from pelican.log import console
 from pelican.log import init as init_logging
 from pelican.generators import (ArticlesGenerator,  # noqa: I100
                                 PagesGenerator, SourceFileGenerator,
@@ -37,13 +36,12 @@ except Exception:
 
 DEFAULT_CONFIG_NAME = 'pelicanconf.py'
 logger = logging.getLogger(__name__)
-console = Console()
 
 
 class Pelican:
 
     def __init__(self, settings):
-        """Pelican initialisation
+        """Pelican initialization
 
         Performs some checks on the environment before doing anything else.
         """
@@ -165,15 +163,15 @@ class Pelican:
             'draft page',
             'draft pages')
 
-        print('Done: Processed {}, {}, {}, {}, {} and {} in {:.2f} seconds.'
-              .format(
-                    pluralized_articles,
-                    pluralized_drafts,
-                    pluralized_hidden_articles,
-                    pluralized_pages,
-                    pluralized_hidden_pages,
-                    pluralized_draft_pages,
-                    time.time() - start_time))
+        console.print('Done: Processed {}, {}, {}, {}, {} and {} in {:.2f} seconds.'
+                      .format(
+                              pluralized_articles,
+                              pluralized_drafts,
+                              pluralized_hidden_articles,
+                              pluralized_pages,
+                              pluralized_hidden_pages,
+                              pluralized_draft_pages,
+                              time.time() - start_time))
 
     def _get_generator_classes(self):
         discovered_generators = [
@@ -224,32 +222,39 @@ class Pelican:
 
         writer = writers[0]
 
-        logger.debug("Found writer: %s", writer)
+        logger.debug("Found writer: %s (%s)", writer.__name__, writer.__module__)
         return writer(self.output_path, settings=self.settings)
 
 
 class PrintSettings(argparse.Action):
     def __call__(self, parser, namespace, values, option_string):
-        instance, settings = get_instance(namespace)
+        init_logging(name=__name__)
+
+        try:
+            instance, settings = get_instance(namespace)
+        except Exception as e:
+            logger.critical("%s: %s", e.__class__.__name__, e)
+            console.print_exception()
+            sys.exit(getattr(e, 'exitcode', 1))
 
         if values:
             # One or more arguments provided, so only print those settings
             for setting in values:
                 if setting in settings:
                     # Only add newline between setting name and value if dict
-                    if isinstance(settings[setting], dict):
+                    if isinstance(settings[setting], (dict, tuple, list)):
                         setting_format = '\n{}:\n{}'
                     else:
                         setting_format = '\n{}: {}'
-                    print(setting_format.format(
+                    console.print(setting_format.format(
                         setting,
                         pprint.pformat(settings[setting])))
                 else:
-                    print('\n{} is not a recognized setting.'.format(setting))
+                    console.print('\n{} is not a recognized setting.'.format(setting))
                     break
         else:
             # No argument was given to --print-settings, so print all settings
-            pprint.pprint(settings)
+            console.print(settings)
 
         parser.exit()
 
@@ -428,8 +433,8 @@ def get_instance(args):
 
 
 def autoreload(args, excqueue=None):
-    print('  --- AutoReload Mode: Monitoring `content`, `theme` and'
-          ' `settings` for changes. ---')
+    console.print('  --- AutoReload Mode: Monitoring `content`, `theme` and'
+                  ' `settings` for changes. ---')
     pelican, settings = get_instance(args)
     watcher = FileSystemWatcher(args.settings, Readers, settings)
     sleep = False
@@ -448,8 +453,8 @@ def autoreload(args, excqueue=None):
                 watcher.update_watchers(settings)
 
             if any(modified.values()):
-                print('\n-> Modified: {}. re-generating...'.format(
-                    ', '.join(k for k, v in modified.items() if v)))
+                console.print('\n-> Modified: {}. re-generating...'.format(
+                              ', '.join(k for k, v in modified.items() if v)))
                 pelican.run()
 
         except KeyboardInterrupt:
@@ -500,8 +505,8 @@ def listen(server, port, output, excqueue=None):
 def main(argv=None):
     args = parse_arguments(argv)
     logs_dedup_min_level = getattr(logging, args.logs_dedup_min_level)
-    init_logging(args.verbosity, args.fatal,
-                 logs_dedup_min_level=logs_dedup_min_level)
+    init_logging(level=args.verbosity, fatal=args.fatal,
+                 name=__name__, logs_dedup_min_level=logs_dedup_min_level)
 
     logger.debug('Pelican version: %s', __version__)
     logger.debug('Python version: %s', sys.version.split()[0])
@@ -538,9 +543,8 @@ def main(argv=None):
     except KeyboardInterrupt:
         logger.warning('Keyboard interrupt received. Exiting.')
     except Exception as e:
-        logger.critical('%s', e)
+        logger.critical("%s: %s", e.__class__.__name__, e)
 
         if args.verbosity == logging.DEBUG:
-            raise
-        else:
-            sys.exit(getattr(e, 'exitcode', 1))
+            console.print_exception()
+        sys.exit(getattr(e, 'exitcode', 1))

pelican/log.py

@@ -1,80 +1,14 @@
 import logging
-import os
-import sys
 from collections import defaultdict
-from collections.abc import Mapping
+
+from rich.console import Console
+from rich.logging import RichHandler
 
 __all__ = [
     'init'
 ]
 
-
-class BaseFormatter(logging.Formatter):
-    def __init__(self, fmt=None, datefmt=None):
-        FORMAT = '%(customlevelname)s %(message)s'
-        super().__init__(fmt=FORMAT, datefmt=datefmt)
-
-    def format(self, record):
-        customlevel = self._get_levelname(record.levelname)
-        record.__dict__['customlevelname'] = customlevel
-        # format multiline messages 'nicely' to make it clear they are together
-        record.msg = record.msg.replace('\n', '\n  | ')
-        if not isinstance(record.args, Mapping):
-            record.args = tuple(arg.replace('\n', '\n  | ') if
-                                isinstance(arg, str) else
-                                arg for arg in record.args)
-        return super().format(record)
-
-    def formatException(self, ei):
-        ''' prefix traceback info for better representation '''
-        s = super().formatException(ei)
-        # fancy format traceback
-        s = '\n'.join('  | ' + line for line in s.splitlines())
-        # separate the traceback from the preceding lines
-        s = '  |___\n{}'.format(s)
-        return s
-
-    def _get_levelname(self, name):
-        ''' NOOP: overridden by subclasses '''
-        return name
-
-
-class ANSIFormatter(BaseFormatter):
-    ANSI_CODES = {
-        'red': '\033[1;31m',
-        'yellow': '\033[1;33m',
-        'cyan': '\033[1;36m',
-        'white': '\033[1;37m',
-        'bgred': '\033[1;41m',
-        'bggrey': '\033[1;100m',
-        'reset': '\033[0;m'}
-
-    LEVEL_COLORS = {
-        'INFO': 'cyan',
-        'WARNING': 'yellow',
-        'ERROR': 'red',
-        'CRITICAL': 'bgred',
-        'DEBUG': 'bggrey'}
-
-    def _get_levelname(self, name):
-        color = self.ANSI_CODES[self.LEVEL_COLORS.get(name, 'white')]
-        if name == 'INFO':
-            fmt = '{0}->{2}'
-        else:
-            fmt = '{0}{1}{2}:'
-        return fmt.format(color, name, self.ANSI_CODES['reset'])
-
-
-class TextFormatter(BaseFormatter):
-    """
-    Convert a `logging.LogRecord' object into text.
-    """
-
-    def _get_levelname(self, name):
-        if name == 'INFO':
-            return '->'
-        else:
-            return name + ':'
+console = Console()
 
 
 class LimitFilter(logging.Filter):
@@ -169,40 +103,20 @@ logging.setLoggerClass(FatalLogger)
 logging.getLogger().__class__ = FatalLogger
 
 
-def supports_color():
-    """
-    Returns True if the running system's terminal supports color,
-    and False otherwise.
-
-    from django.core.management.color
-    """
-    plat = sys.platform
-    supported_platform = plat != 'Pocket PC' and \
-        (plat != 'win32' or 'ANSICON' in os.environ)
-
-    # isatty is not always implemented, #6223.
-    is_a_tty = hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()
-    if not supported_platform or not is_a_tty:
-        return False
-    return True
-
-
-def get_formatter():
-    if supports_color():
-        return ANSIFormatter()
-    else:
-        return TextFormatter()
-
-
-def init(level=None, fatal='', handler=logging.StreamHandler(), name=None,
+def init(level=None, fatal='', handler=RichHandler(console=console), name=None,
          logs_dedup_min_level=None):
     FatalLogger.warnings_fatal = fatal.startswith('warning')
     FatalLogger.errors_fatal = bool(fatal)
 
-    logger = logging.getLogger(name)
+    LOG_FORMAT = "%(message)s"
+    logging.basicConfig(
+        level=level,
+        format=LOG_FORMAT,
+        datefmt="[%H:%M:%S]",
+        handlers=[handler]
+    )
 
-    handler.setFormatter(get_formatter())
-    logger.addHandler(handler)
+    logger = logging.getLogger(name)
 
     if level:
         logger.setLevel(level)
@@ -218,9 +132,9 @@ def log_warnings():
 
 
 if __name__ == '__main__':
-    init(level=logging.DEBUG)
+    init(level=logging.DEBUG, name=__name__)
 
-    root_logger = logging.getLogger()
+    root_logger = logging.getLogger(__name__)
     root_logger.debug('debug')
     root_logger.info('info')
     root_logger.warning('warning')

pelican/tests/test_log.py

@@ -12,12 +12,10 @@ class TestLog(unittest.TestCase):
         super().setUp()
         self.logger = logging.getLogger(__name__)
         self.handler = LogCountHandler()
-        self.handler.setFormatter(log.get_formatter())
         self.logger.addHandler(self.handler)
 
     def tearDown(self):
         self._reset_limit_filter()
-        self.logger.removeHandler(self.handler)
         super().tearDown()
 
     def _reset_limit_filter(self):
@@ -34,54 +32,6 @@ class TestLog(unittest.TestCase):
             self._reset_limit_filter()
             self.handler.flush()
 
-    def test_log_formatter(self):
-        counter = self.handler.count_formatted_logs
-        with self.reset_logger():
-            # log simple case
-            self.logger.warning('Log %s', 'test')
-            self.assertEqual(
-                counter('Log test', logging.WARNING),
-                1)
-
-        with self.reset_logger():
-            # log multiline message
-            self.logger.warning('Log\n%s', 'test')
-            # Log
-            # | test
-            self.assertEqual(
-                counter('Log', logging.WARNING),
-                1)
-            self.assertEqual(
-                counter(' | test', logging.WARNING),
-                1)
-
-        with self.reset_logger():
-            # log multiline argument
-            self.logger.warning('Log %s', 'test1\ntest2')
-            # Log test1
-            # | test2
-            self.assertEqual(
-                counter('Log test1', logging.WARNING),
-                1)
-            self.assertEqual(
-                counter(' | test2', logging.WARNING),
-                1)
-
-        with self.reset_logger():
-            # log single list
-            self.logger.warning('Log %s', ['foo', 'bar'])
-            self.assertEqual(
-                counter(r"Log \['foo', 'bar'\]", logging.WARNING),
-                1)
-
-        with self.reset_logger():
-            # log single dict
-            self.logger.warning('Log %s', {'foo': 1, 'bar': 2})
-            self.assertEqual(
-                # dict order is not guaranteed
-                counter(r"Log {'.*': \d, '.*': \d}", logging.WARNING),
-                1)
-
     def test_log_filter(self):
         def do_logging():
             for i in range(5):

pelican/utils.py

@@ -827,7 +827,7 @@ class FileSystemWatcher:
         if result.get('content') is None:
             reader_descs = sorted(
                 {
-                    '%s (%s)' % (type(r).__name__, ', '.join(r.file_extensions))
+                    '  | %s (%s)' % (type(r).__name__, ', '.join(r.file_extensions))
                     for r in self.reader_class(self.settings).readers.values()
                     if r.enabled
                 }