Merge pull request #206 from voith/test-logger

added tests for filters, formatters, handlers

frontera/logger/filters/__init__.py

@@ -1,27 +1,22 @@
 from __future__ import absolute_import
 import logging
 import six
-
-
-def format_str(s):
-    if isinstance(s, six.text_type):
-        return s.encode('ascii', 'ignore')
-    return str(s)
+from w3lib.util import to_native_str
 
 
 class PlainValuesFilter(logging.Filter):
     def __init__(self, separator=None, excluded_fields=None, msg_max_length=0):
         super(PlainValuesFilter, self).__init__()
-        self.separator = separator or " "
+        self.separator = to_native_str(separator or " ")
         self.excluded_fields = excluded_fields or []
         self.msg_max_length = msg_max_length
 
     def filter(self, record):
         if isinstance(record.msg, dict):
             for field_name in self.excluded_fields:
                 setattr(record, field_name, record.msg.get(field_name, ''))
-            record.msg = self.separator.join([format_str(value)
-                                              for key, value in record.msg.items()
+            record.msg = self.separator.join([to_native_str(value)
+                                              for key, value in six.iteritems(record.msg)
                                               if key not in self.excluded_fields])
             if self.msg_max_length and len(record.msg) > self.msg_max_length:
                 record.msg = record.msg[0:self.msg_max_length-3] + "..."

frontera/logger/formatters/__init__.py

@@ -1,10 +1,7 @@
 from __future__ import absolute_import
 import logging
 
-from .text import DETAILED, SHORT
-
 LOG_FORMAT = "[%(name)s] %(message)s"
-LOG_EVENT_FORMAT = "%(asctime)s %(event)-16s %(message)s"
 
 try:
     from .color import ColorFormatter
@@ -18,41 +15,9 @@
         "CRITICAL": "bold_purple",
     }
 
-    EVENTS = ColorFormatter(
-        format="%(log_color)s"+LOG_EVENT_FORMAT,
-        log_colors={
-            "FRONTIER_START": "bold_yellow",
-            "FRONTIER_STOP": "bold_yellow",
-            "ADD_SEED": "cyan",
-            "ADD_SEEDS": "cyan",
-            "PAGE_CRAWLED": "blue",
-            "PAGE_CRAWLED_ERROR": "red",
-            "GET_NEXT_PAGES": "purple",
-        },
-        log_color_field="event")
-
     CONSOLE = ColorFormatter(
         format=LOG_COLOR_FORMAT,
         log_colors=COLORS.copy(),
         log_color_field="levelname")
-
-    CONSOLE_MANAGER = ColorFormatter(
-        format=LOG_COLOR_FORMAT,
-        log_colors=COLORS.copy(),
-        log_color_field="levelname")
-
-    CONSOLE_BACKEND = ColorFormatter(
-        format=LOG_COLOR_FORMAT,
-        log_colors=COLORS.copy(),
-        log_color_field="levelname")
-
-    CONSOLE_DEBUGGING = ColorFormatter(
-        format=LOG_COLOR_FORMAT,
-        log_colors=COLORS.copy(),
-        log_color_field="levelname")
 except ImportError:
-    EVENTS = logging.Formatter(fmt=LOG_EVENT_FORMAT)
     CONSOLE = logging.Formatter(fmt=LOG_FORMAT)
-    CONSOLE_MANAGER = logging.Formatter(fmt=LOG_FORMAT)
-    CONSOLE_BACKEND = logging.Formatter(fmt=LOG_FORMAT)
-    CONSOLE_DEBUGGING = logging.Formatter(fmt=LOG_FORMAT)

frontera/logger/formatters/json.py

@@ -1,21 +1,7 @@
 from __future__ import absolute_import
 
 from pythonjsonlogger.jsonlogger import JsonFormatter
-
-import datetime
-from json import JSONEncoder
-
-
-class DateTimeEncoder(JSONEncoder):
-    def default(self, obj):
-        if isinstance(obj, datetime.datetime):
-            return obj.isoformat()
-        elif isinstance(obj, datetime.date):
-            return obj.isoformat()
-        elif isinstance(obj, datetime.timedelta):
-            return (datetime.datetime.min + obj).time().isoformat()
-        else:
-            return super(DateTimeEncoder, self).default(obj)
+from frontera.utils.encoders import DateTimeEncoder
 
 
 class JSONFormatter(JsonFormatter):

frontera/logger/handlers/__init__.py

@@ -2,22 +2,7 @@
 import sys
 import logging
 
-from frontera.logger import filters, formatters
-
-
-EVENTS = logging.StreamHandler(stream=sys.stdout)
-EVENTS.setFormatter(formatters.EVENTS)
-EVENTS.setLevel(logging.INFO)
-EVENTS.filters.append(filters.PLAINVALUES(excluded_fields=['event']))
+from frontera.logger import formatters
 
 CONSOLE = logging.StreamHandler(stream=sys.stdout)
 CONSOLE.setFormatter(formatters.CONSOLE)
-
-CONSOLE_MANAGER = logging.StreamHandler(stream=sys.stdout)
-CONSOLE_MANAGER.setFormatter(formatters.CONSOLE_MANAGER)
-
-CONSOLE_BACKEND = logging.StreamHandler(stream=sys.stdout)
-CONSOLE_BACKEND.setFormatter(formatters.CONSOLE_BACKEND)
-
-CONSOLE_DEBUGGING = logging.StreamHandler(stream=sys.stdout)
-CONSOLE_DEBUGGING.setFormatter(formatters.CONSOLE_DEBUGGING)

requirements/logging.txt

@@ -1 +1,2 @@
 colorlog>=2.4.0
+python-json-logger>=0.1.5

requirements/tests.txt

@@ -12,3 +12,4 @@ pytest-cov
 happybase>=1.0.0
 mock
 boto>=2.42.0
+-r logging.txt

setup.py

@@ -54,6 +54,7 @@
         ],
         'logging': [
             'colorlog>=2.4.0',
+            'python-json-logger>=0.1.5'
         ],
         'tldextract': [
             'tldextract>=1.5.1',
@@ -82,6 +83,8 @@
         "SQLAlchemy>=1.0.0",
         "cachetools",
         "mock",
-        "boto>=2.42.0"
+        "boto>=2.42.0",
+        "colorlog>=2.4.0",
+        "python-json-logger>=0.1.5"
     ]
 )

tests/test_filters.py

@@ -0,0 +1,122 @@
+import unittest
+
+from frontera.logger.filters import PLAINVALUES, INCLUDEFIELDS, EXCLUDEFIELDS
+from tests.utils import LoggingCaptureMixin, SetupDefaultLoggingMixin
+
+
+class BaseTestFilters(SetupDefaultLoggingMixin, LoggingCaptureMixin, unittest.TestCase):
+    def tearDown(self):
+        super(BaseTestFilters, self).setUp()
+        self.logger.handlers[0].filters = []
+
+    def addFilter(self, filter):
+        self.logger.handlers[0].addFilter(filter)
+
+
+class TestFilterPlainValues(BaseTestFilters):
+    def test_plain_values_exclude_fields(self):
+        filter = PLAINVALUES(excluded_fields=['event'])
+        self.addFilter(filter)
+        self.logger.debug({'message1': 'logging', 'message2': 'debug', 'event': 'value'})
+        log_msg = self.logger_output.getvalue()
+        assert log_msg == 'logging debug\n' or log_msg == 'debug logging\n'
+
+    def test_plain_values_separator(self):
+        filter = PLAINVALUES(separator=',')
+        self.addFilter(filter)
+        self.logger.debug({'message1': 'logging', 'message2': 'debug'})
+        log_msg = self.logger_output.getvalue()
+        assert log_msg == 'logging,debug\n' or log_msg == 'debug,logging\n'
+
+    def test_plain_values_msg_max_length(self):
+        filter = PLAINVALUES(msg_max_length=10)
+        self.addFilter(filter)
+        self.logger.debug({'message1': '1' * 10, 'message2': '2' * 10})
+        log_msg = self.logger_output.getvalue()
+        assert log_msg == '%s...\n' % ('1' * 7) or log_msg == '%s...\n' % ('2' * 7)
+
+    def test_plain_values_str_msg(self):
+        filter = PLAINVALUES(msg_max_length=10)
+        self.addFilter(filter)
+        self.logger.debug('debug message')
+        self.assertEqual(self.logger_output.getvalue(), 'debug message\n')
+
+
+class TestIncludeFields(BaseTestFilters):
+    def test_include_fields_matching_values(self):
+        filter = INCLUDEFIELDS(field_name='event', included_values=['page_crawled'])
+        self.addFilter(filter)
+        self.logger.debug('crawled page P', extra={'event': 'page_crawled'})
+        self.assertEqual(self.logger_output.getvalue(), 'crawled page P\n')
+
+    def test_include_fields_non_matching_values(self):
+        filter = INCLUDEFIELDS(field_name='event', included_values=['links_extracted'])
+        self.addFilter(filter)
+        self.logger.debug('crawled page P', extra={'event': 'page_crawled'})
+        self.assertEqual(self.logger_output.getvalue(), '')
+
+    def test_include_fields_dict_msg_matching_values(self):
+        filter = INCLUDEFIELDS(field_name='event', included_values=['page_crawled'])
+        self.addFilter(filter)
+        self.logger.debug({'message': 'debug message', 'event': 'page_crawled'})
+        log_msg = self.logger_output.getvalue()
+        assert log_msg == "{'event': 'page_crawled', 'message': 'debug message'}\n" or \
+               log_msg == "{'message': 'debug message', 'event': 'page_crawled'}\n"
+
+    def test_include_fields_dict_msg_non_matching_values(self):
+        filter = INCLUDEFIELDS(field_name='event', included_values=['links_extracted'])
+        self.addFilter(filter)
+        self.logger.debug({'message': 'debug message', 'event': 'page_crawled'})
+        self.assertEqual(self.logger_output.getvalue(), '')
+
+    def test_include_fields_field_name_none(self):
+        filter = INCLUDEFIELDS(field_name=None, included_values=[])
+        self.addFilter(filter)
+        self.logger.debug('debug message')
+        self.assertEqual(self.logger_output.getvalue(), 'debug message\n')
+
+    def test_include_fields_list_message(self):
+        filter = INCLUDEFIELDS(field_name='event', included_values=['page_crawled'])
+        self.addFilter(filter)
+        self.logger.debug(['debug message'])
+        self.assertEqual(self.logger_output.getvalue(), "['debug message']\n")
+
+
+class TestExcludeFields(BaseTestFilters):
+    def test_exclude_fields_matching_values(self):
+        filter = EXCLUDEFIELDS(field_name='event', excluded_fields=['page_crawled'])
+        self.addFilter(filter)
+        self.logger.debug('crawled page P', extra={'event': 'page_crawled'})
+        self.assertEqual(self.logger_output.getvalue(), '')
+
+    def test_exclude_fields_non_matching_values(self):
+        filter = EXCLUDEFIELDS(field_name='event', excluded_fields=['links_extracted'])
+        self.addFilter(filter)
+        self.logger.debug('crawled page P', extra={'event': 'page_crawled'})
+        self.assertEqual(self.logger_output.getvalue(), 'crawled page P\n')
+
+    def test_exclude_fields_dict_msg_matching_values(self):
+        filter = EXCLUDEFIELDS(field_name='event', excluded_fields='page_crawled')
+        self.addFilter(filter)
+        self.logger.debug({'message': 'debug message', 'event': 'page_crawled'})
+        self.assertEqual(self.logger_output.getvalue(), '')
+
+    def test_exclude_fields_dict_msg_non_matching_values(self):
+        filter = EXCLUDEFIELDS(field_name='event', excluded_fields='links_extracted')
+        self.addFilter(filter)
+        self.logger.debug({'message': 'debug message', 'event': 'page_crawled'})
+        log_msg = self.logger_output.getvalue()
+        assert log_msg == "{'event': 'page_crawled', 'message': 'debug message'}\n" or \
+               log_msg == "{'message': 'debug message', 'event': 'page_crawled'}\n"
+
+    def test_include_fields_field_name_none(self):
+        filter = EXCLUDEFIELDS(field_name=None, excluded_fields=[])
+        self.addFilter(filter)
+        self.logger.debug('debug message')
+        self.assertEqual(self.logger_output.getvalue(), 'debug message\n')
+
+    def test_include_fields_list_message(self):
+        filter = EXCLUDEFIELDS(field_name='event', excluded_fields=['page_crawled'])
+        self.addFilter(filter)
+        self.logger.debug(['debug message'])
+        self.assertEqual(self.logger_output.getvalue(), "['debug message']\n")