Added tests for filters, formatters, handlers

.travis.yml

@@ -5,6 +5,7 @@ services:
   - docker
   - mysql
   - postgresql
+  - redis-server
 
 env:
   global:
@@ -21,6 +22,7 @@ matrix:
         - docker
         - mysql
         - postgresql
+        - redis-server
 
 install:
   - pip install -U tox wheel codecov

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/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/redis.py

@@ -18,7 +18,7 @@ class RedisListHandler(logging.Handler):
 
     @classmethod
     def to(cls, list_name, max_messages=None, host='localhost', port=6379, level=logging.NOTSET):
-        return cls(list_name, max_messages, redis.Redis(host=host, port=port), level=level)
+        return cls(list_name, max_messages=max_messages, redis_client=redis.Redis(host=host, port=port), level=level)
 
     def __init__(self, list_name, formatter=None, filters=None, max_messages=None,
                  redis_client=None, host='localhost', port=6379,

requirements/logging.txt

@@ -1 +1,3 @@
 colorlog>=2.4.0
+python-json-logger>=0.1.5
+redis>=2.10.5

requirements/tests.txt

@@ -10,3 +10,4 @@ msgpack-python
 kafka-python<=0.9.5
 pytest-cov
 happybase>=1.0.0
+-r logging.txt

setup.py

@@ -54,6 +54,8 @@
         ],
         'logging': [
             'colorlog>=2.4.0',
+            'python-json-logger>=0.1.5',
+            'redis>=2.10.5'
         ],
         'tldextract': [
             'tldextract>=1.5.1',
@@ -80,6 +82,9 @@
         "scrapy>=0.24",
         "tldextract>=1.5.1",
         "SQLAlchemy>=1.0.0",
-        "cachetools"
+        "cachetools",
+        "colorlog>=2.4.0",
+        "python-json-logger>=0.1.5",
+        "redis>=2.10.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")

tests/test_formatters.py

@@ -0,0 +1,155 @@
+import unittest
+import re
+import json
+import datetime
+
+from frontera.logger.formatters.text import DETAILED, SHORT
+from frontera.logger.formatters.color import ColorFormatter
+from frontera.logger.formatters.json import JSONFormatter
+from frontera.logger.formatters import (EVENTS,
+                                        CONSOLE,
+                                        CONSOLE_MANAGER,
+                                        CONSOLE_BACKEND,
+                                        CONSOLE_DEBUGGING)
+from tests.utils import LoggingCaptureMixin, SetupDefaultLoggingMixin, colors
+
+
+class BaseTestFormatters(SetupDefaultLoggingMixin, LoggingCaptureMixin, unittest.TestCase):
+    def setUp(self):
+        super(BaseTestFormatters, self).setUp()
+        self.default_formatter = self.logger.handlers[0].formatter
+
+    def tearDown(self):
+        super(BaseTestFormatters, self).setUp()
+        self.logger.handlers[0].formatter = self.default_formatter
+
+    def setFormatter(self, formatter):
+        self.logger.handlers[0].setFormatter(formatter)
+
+
+class TestFormatterText(BaseTestFormatters):
+
+    def test_formatter_detailed(self):
+        self.setFormatter(DETAILED)
+        self.logger.debug('debug message')
+        self.assertRegexpMatches(self.logger_output.getvalue(),
+                                 r'\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d+ - frontera - DEBUG - debug message\n')
+
+    def test_formatter_short(self):
+        self.setFormatter(SHORT)
+        self.logger.debug('debug message')
+        self.assertEqual(self.logger_output.getvalue(), '[frontera]   DEBUG: debug message\n')
+
+
+class TestFormatterColor(BaseTestFormatters):
+
+    def test_formatter_color(self):
+        c = ColorFormatter(
+            format="%(log_color)s [%(name)s] %(message)s",
+            log_colors={
+                "DEBUG": "white",
+                "INFO": "green",
+                "ERROR": "red",
+            },
+            log_color_field="levelname")
+        self.setFormatter(c)
+        self.logger.debug('debug message')
+        self.logger.info('info message')
+        self.logger.error('error message')
+        self.assertEqual(self.logger_output.getvalue(),
+                         '{white} [frontera] debug message{reset}\n'
+                         '{green} [frontera] info message{reset}\n'
+                         '{red} [frontera] error message{reset}\n'.format(white=colors['white'],
+                                                                          green=colors['green'],
+                                                                          red=colors['red'],
+                                                                          reset=colors['reset']))
+
+    def test_formatter_color_datefmt(self):
+        c = ColorFormatter(
+            format="%(log_color)s %(asctime)s [%(name)s] %(message)s",
+            log_colors={
+                "DEBUG": "white",
+                "INFO": "green",
+                "ERROR": "red",
+            },
+            datefmt='%d-%m-%Y %H:%M:%S',
+            log_color_field="levelname")
+        self.setFormatter(c)
+        self.logger.debug('debug message')
+        self.assertRegexpMatches(self.logger_output.getvalue(),
+                                 '{white} \d{{2}}-\d{{2}}-\d{{4}} \d{{2}}:\d{{2}}:\d{{2}} '
+                                 '\\[frontera\\] debug message{reset}\n'.format(
+                                     white=re.escape(colors['white']),
+                                     reset=re.escape(colors['reset'])))
+
+
+class TestFormatterJson(BaseTestFormatters):
+
+    def setUp(self):
+        super(TestFormatterJson, self).setUp()
+        self.setFormatter(JSONFormatter())
+
+    def test_formatter_json_log_text(self):
+        self.logger.debug('debug message')
+        self.assertEqual(json.loads(self.logger_output.getvalue())['message'], 'debug message')
+
+    def test_formatter_json_log_dict(self):
+        dct_msg = {
+            'message': 'debug message',
+            'extra': 'value',
+        }
+        self.logger.debug(dct_msg)
+        json_log = json.loads(self.logger_output.getvalue())
+        self.assertEqual(json_log.get('message'), 'debug message')
+        self.assertEqual(json_log.get('extra'), 'value')
+
+    def test_formatter_json_log_datetime_objects(self):
+        dct_msg = {
+            'message': 'debug message',
+            'datetime': datetime.datetime(2016, 9, 19, 23, 59),
+            'date': datetime.date(2016, 9, 20),
+            'timedelta': datetime.datetime(2016, 9, 19, 23, 59) - datetime.datetime(2016, 9, 19, 23, 50),
+        }
+        self.logger.debug(dct_msg)
+        json_log = json.loads(self.logger_output.getvalue())
+        self.assertEqual(json_log.get('message'), 'debug message')
+        self.assertEqual(json_log.get('datetime'), '2016-09-19T23:59:00')
+        self.assertEqual(json_log.get('date'), '2016-09-20')
+        self.assertEqual(json_log.get('timedelta'), '00:09:00')
+
+
+class TestFormatterMiscellaneous(BaseTestFormatters):
+    def test_formatter_events(self):
+
+        self.setFormatter(EVENTS)
+        self.logger.debug('starting frontier', extra={'event': 'FRONTIER_START'})
+        self.assertRegexpMatches(self.logger_output.getvalue(),
+                                 r'{bold_yellow}\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}},\d+ '
+                                 r'FRONTIER_START   starting frontier{reset}\n'.
+                                 format(bold_yellow=re.escape(colors['bold_yellow']),
+                                        reset=re.escape(colors['reset'])))
+
+    def test_formatter_console(self):
+        self.assert_logs(CONSOLE)
+
+    def test_formatter_console_manager(self):
+        self.assert_logs(CONSOLE_MANAGER)
+
+    def test_formatter_console_backend(self):
+        self.assert_logs(CONSOLE_BACKEND)
+
+    def test_formatter_console_debugging(self):
+        self.assert_logs(CONSOLE_DEBUGGING)
+
+    def assert_logs(self, formatter):
+        self.setFormatter(formatter)
+        self.logger.debug('debug message')
+        self.logger.info('info message')
+        self.logger.error('error message')
+        self.assertEqual(self.logger_output.getvalue(),
+                         '{white}[frontera] debug message{reset}\n'
+                         '{green}[frontera] info message{reset}\n'
+                         '{red}[frontera] error message{reset}\n'.format(white=colors['white'],
+                                                                         green=colors['green'],
+                                                                         red=colors['red'],
+                                                                         reset=colors['reset']))