Fix dictionary logging in formatter

Python special cases single Mapping arguments to logging. This
adjusts BaseFormatter to skip "fancy" formatting if argument
is of type Mapping. Also adds various formatted log outputs.

pelican/log.py

@@ -2,6 +2,7 @@ import logging
 import os
 import sys
 from collections import defaultdict
+from collections.abc import Mapping
 
 __all__ = [
     'init'
@@ -18,9 +19,10 @@ class BaseFormatter(logging.Formatter):
         record.__dict__['customlevelname'] = customlevel
         # format multiline messages 'nicely' to make it clear they are together
         record.msg = record.msg.replace('\n', '\n  | ')
-        record.args = tuple(arg.replace('\n', '\n  | ') if
-                            isinstance(arg, str) else
-                            arg for arg in record.args)
+        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):

pelican/tests/support.py

@@ -195,6 +195,15 @@ class LogCountHandler(BufferingHandler):
                (level is None or l.levelno == level)
         ])
 
+    def count_formatted_logs(self, msg=None, level=None):
+        return len([
+            l
+            for l
+            in self.buffer
+            if (msg is None or re.search(msg, self.format(l))) and
+               (level is None or l.levelno == level)
+        ])
+
 
 class LoggedTestCase(unittest.TestCase):
     """A test case that captures log messages."""

pelican/tests/test_log.py

@@ -12,6 +12,7 @@ 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):
@@ -33,6 +34,54 @@ 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):