From c19075816bd7b909421bbf20a463f332ee9e03be Mon Sep 17 00:00:00 2001 From: Deniz Turgut Date: Sat, 9 May 2020 19:30:21 +0300 Subject: [PATCH 1/2] use context manager for log testing --- pelican/tests/test_log.py | 85 +++++++++++++++++++++------------------ 1 file changed, 45 insertions(+), 40 deletions(-) diff --git a/pelican/tests/test_log.py b/pelican/tests/test_log.py index 90a4552d..41fd69ae 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 @@ -24,55 +25,59 @@ 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_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) From 50281c42e5bd8d170bd666668ae527170997f357 Mon Sep 17 00:00:00 2001 From: Deniz Turgut Date: Sat, 9 May 2020 19:39:54 +0300 Subject: [PATCH 2/2] 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 | 8 ++++--- pelican/tests/support.py | 9 +++++++ pelican/tests/test_log.py | 49 +++++++++++++++++++++++++++++++++++++++ 3 files changed, 63 insertions(+), 3 deletions(-) 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 8a22052e..b6b547cd 100644 --- a/pelican/tests/support.py +++ b/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.""" diff --git a/pelican/tests/test_log.py b/pelican/tests/test_log.py index 41fd69ae..3f9d7250 100644 --- a/pelican/tests/test_log.py +++ b/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):