diff --git a/pelican/log.py b/pelican/log.py index ac5034d9..8b7869ac 100644 --- a/pelican/log.py +++ b/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): diff --git a/pelican/tests/support.py b/pelican/tests/support.py index e52bc0ae..e85f26f2 100644 --- a/pelican/tests/support.py +++ b/pelican/tests/support.py @@ -208,6 +208,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.""" diff --git a/pelican/tests/test_log.py b/pelican/tests/test_log.py index 90a4552d..3f9d7250 100644 --- a/pelican/tests/test_log.py +++ b/pelican/tests/test_log.py @@ -1,6 +1,7 @@ import logging import unittest from collections import defaultdict +from contextlib import contextmanager from pelican import log from pelican.tests.support import LogCountHandler @@ -11,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): @@ -24,55 +26,107 @@ class TestLog(unittest.TestCase): log.LimitFilter._threshold = 5 log.LimitFilter._group_count = defaultdict(int) + @contextmanager + def reset_logger(self): + try: + yield None + finally: + 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): self.logger.warning('Log %s', i) self.logger.warning('Another log %s', i) # no filter - do_logging() - self.assertEqual( - self.handler.count_logs('Log \\d', logging.WARNING), - 5) - self.assertEqual( - self.handler.count_logs('Another log \\d', logging.WARNING), - 5) - self.handler.flush() - self._reset_limit_filter() + with self.reset_logger(): + do_logging() + self.assertEqual( + self.handler.count_logs('Log \\d', logging.WARNING), + 5) + self.assertEqual( + self.handler.count_logs('Another log \\d', logging.WARNING), + 5) # filter by template - log.LimitFilter._ignore.add((logging.WARNING, 'Log %s')) - do_logging() - self.assertEqual( - self.handler.count_logs('Log \\d', logging.WARNING), - 0) - self.assertEqual( - self.handler.count_logs('Another log \\d', logging.WARNING), - 5) - self.handler.flush() - self._reset_limit_filter() + with self.reset_logger(): + log.LimitFilter._ignore.add((logging.WARNING, 'Log %s')) + do_logging() + self.assertEqual( + self.handler.count_logs('Log \\d', logging.WARNING), + 0) + self.assertEqual( + self.handler.count_logs('Another log \\d', logging.WARNING), + 5) # filter by exact message - log.LimitFilter._ignore.add((logging.WARNING, 'Log 3')) - do_logging() - self.assertEqual( - self.handler.count_logs('Log \\d', logging.WARNING), - 4) - self.assertEqual( - self.handler.count_logs('Another log \\d', logging.WARNING), - 5) - self.handler.flush() - self._reset_limit_filter() + with self.reset_logger(): + log.LimitFilter._ignore.add((logging.WARNING, 'Log 3')) + do_logging() + self.assertEqual( + self.handler.count_logs('Log \\d', logging.WARNING), + 4) + self.assertEqual( + self.handler.count_logs('Another log \\d', logging.WARNING), + 5) # filter by both - log.LimitFilter._ignore.add((logging.WARNING, 'Log 3')) - log.LimitFilter._ignore.add((logging.WARNING, 'Another log %s')) - do_logging() - self.assertEqual( - self.handler.count_logs('Log \\d', logging.WARNING), - 4) - self.assertEqual( - self.handler.count_logs('Another log \\d', logging.WARNING), - 0) - self.handler.flush() - self._reset_limit_filter() + with self.reset_logger(): + log.LimitFilter._ignore.add((logging.WARNING, 'Log 3')) + log.LimitFilter._ignore.add((logging.WARNING, 'Another log %s')) + do_logging() + self.assertEqual( + self.handler.count_logs('Log \\d', logging.WARNING), + 4) + self.assertEqual( + self.handler.count_logs('Another log \\d', logging.WARNING), + 0)