Refactor logging handling

Old system was using manual string formatting for log messages.
This caused issues with common operations like exception logging
because often they need to be handled differently for Py2/Py3
compatibility. In order to unify the effort:

 - All logging is changed to `logging.level(msg, arg1, arg2)` style.
 - A `SafeLogger` is implemented to auto-decode exceptions properly
in the args (ref #1403).
 - Custom formatters were overriding useful logging functionality
like traceback outputing (ref #1402). They are refactored to be
more transparent. Traceback information is provided in `--debug`
mode for `read_file` errors in generators.
 - Formatters will now auto-format multiline log messages in order
to make them look related. Similarly, traceback will be formatted in
the same fashion.
 - `pelican.log.LimitFilter` was (ab)using logging message which
would result in awkward syntax for argumented logging style. This
functionality is moved to `extra` keyword argument.
 - Levels for errors that would result skipping a file (`read_file`)
changed from `warning` to `error` in order to make them stand out
among other logs.
 - Small consistency changes to log messages (i.e. changing all
to start with an uppercase letter) and quality-of-life improvements
(some log messages were dumping raw object information).

pelican/log.py

@@ -8,59 +8,76 @@ __all__ = [
 import os
 import sys
 import logging
+import locale
 
-from collections import defaultdict
+from collections import defaultdict, Mapping
 
+import six
 
-RESET_TERM = '\033[0;m'
+class BaseFormatter(logging.Formatter):
+    def __init__(self, fmt=None, datefmt=None):
+        FORMAT = '%(customlevelname)s %(message)s'
+        super(BaseFormatter, self).__init__(fmt=FORMAT, datefmt=datefmt)
 
-COLOR_CODES = {
-    'red': 31,
-    'yellow': 33,
-    'cyan': 36,
-    'white': 37,
-    'bgred': 41,
-    'bggrey': 100,
-}
-
-
-def ansi(color, text):
-    """Wrap text in an ansi escape sequence"""
-    code = COLOR_CODES[color]
-    return '\033[1;{0}m{1}{2}'.format(code, text, RESET_TERM)
-
-
-class ANSIFormatter(logging.Formatter):
-    """Convert a `logging.LogRecord' object into colored text, using ANSI
-       escape sequences.
-
-    """
     def format(self, record):
-        msg = record.getMessage()
-        if record.levelname == 'INFO':
-            return ansi('cyan', '-> ') + msg
-        elif record.levelname == 'WARNING':
-            return ansi('yellow', record.levelname) + ': ' + msg
-        elif record.levelname == 'ERROR':
-            return ansi('red', record.levelname) + ': ' + msg
-        elif record.levelname == 'CRITICAL':
-            return ansi('bgred', record.levelname) + ': ' + msg
-        elif record.levelname == 'DEBUG':
-            return ansi('bggrey', record.levelname) + ': ' + msg
+        record.__dict__['customlevelname'] = self._get_levelname(record.levelname)
+        # format multiline messages 'nicely' to make it clear they are together
+        record.msg = record.msg.replace('\n', '\n  | ')
+        return super(BaseFormatter, self).format(record)
+
+    def formatException(self, ei):
+        ''' prefix traceback info for better representation '''
+        # .formatException returns a bytestring in py2 and unicode in py3
+        # since .format will handle unicode conversion,
+        # str() calls are used to normalize formatting string
+        s = super(BaseFormatter, self).formatException(ei)
+        # fancy format traceback
+        s = str('\n').join(str('  | ') + line for line in s.splitlines())
+        # seperate the traceback from the preceding lines
+        s = str('  |___\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:
-            return ansi('white', record.levelname) + ': ' + msg
+            fmt = '{0}{1}{2}:'
+        return fmt.format(color, name, self.ANSI_CODES['reset'])
 
 
-class TextFormatter(logging.Formatter):
+class TextFormatter(BaseFormatter):
     """
     Convert a `logging.LogRecord' object into text.
     """
 
-    def format(self, record):
-        if not record.levelname or record.levelname == 'INFO':
-            return record.getMessage()
+    def _get_levelname(self, name):
+        if name == 'INFO':
+            return '->'
         else:
-            return record.levelname + ': ' + record.getMessage()
+            return name + ':'
 
 
 class LimitFilter(logging.Filter):
@@ -73,37 +90,74 @@ class LimitFilter(logging.Filter):
     E.g.: log.warning(('43 is not the answer', 'More erroneous answers'))
     """
 
-    ignore = set()
-    threshold = 5
-    group_count = defaultdict(int)
+    _ignore = set()
+    _threshold = 5
+    _group_count = defaultdict(int)
 
     def filter(self, record):
         # don't limit log messages for anything above "warning"
         if record.levelno > logging.WARN:
-            return record
+            return True
+
         # extract group
-        group = None
-        if len(record.msg) == 2:
-            record.msg, group = record.msg
+        group = record.__dict__.get('limit_msg', None)
+        group_args = record.__dict__.get('limit_args', ())
+
         # ignore record if it was already raised
         # use .getMessage() and not .msg for string formatting
         ignore_key = (record.levelno, record.getMessage())
-        to_ignore = ignore_key in LimitFilter.ignore
-        LimitFilter.ignore.add(ignore_key)
-        if to_ignore:
+        if ignore_key in self._ignore:
             return False
+        else:
+            self._ignore.add(ignore_key)
+
         # check if we went over threshold
         if group:
             key = (record.levelno, group)
-            LimitFilter.group_count[key] += 1
-            if LimitFilter.group_count[key] == LimitFilter.threshold:
+            self._group_count[key] += 1
+            if self._group_count[key] == self._threshold:
                 record.msg = group
-            if LimitFilter.group_count[key] > LimitFilter.threshold:
+                record.args = group_args
+            elif self._group_count[key] > self._threshold:
                 return False
-        return record
+        return True
 
 
-class LimitLogger(logging.Logger):
+class SafeLogger(logging.Logger):
+    """
+    Base Logger which properly encodes Exceptions in Py2
+    """
+    _exc_encoding = locale.getpreferredencoding()
+
+    def _log(self, level, msg, args, exc_info=None, extra=None):
+        # if the only argument is a Mapping, Logger uses that for formatting
+        # format values for that case
+        if args and len(args)==1 and isinstance(args[0], Mapping):
+            args = ({k: self._decode_arg(v) for k, v in args[0].items()},)
+        # otherwise, format each arg
+        else:
+            args = tuple(self._decode_arg(arg) for arg in args)
+        super(SafeLogger, self)._log(level, msg, args,
+            exc_info=exc_info, extra=extra)
+
+    def _decode_arg(self, arg):
+        '''
+        properly decode an arg for Py2 if it's Exception
+
+
+        localized systems have errors in native language if locale is set
+        so convert the message to unicode with the correct encoding
+        '''
+        if isinstance(arg, Exception):
+            text = str(arg)
+            if six.PY2:
+                text = text.decode(self._exc_encoding)
+            return text
+        else:
+            return arg
+
+
+class LimitLogger(SafeLogger):
     """
     A logger which adds LimitFilter automatically
     """