added tests for formatters

scrapinghub · Sep 20, 2016 · 6fbe310 · 6fbe310
1 parent dba96ae
commit 6fbe310
Show file tree

Hide file tree

Showing 6 changed files with 225 additions and 16 deletions.
diff --git a/frontera/logger/formatters/json.py b/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):

diff --git a/requirements/logging.txt b/requirements/logging.txt
@@ -1 +1,2 @@
 colorlog>=2.4.0
+python-json-logger>=0.1.5
diff --git a/requirements/tests.txt b/requirements/tests.txt
@@ -10,3 +10,4 @@ msgpack-python
 kafka-python<=0.9.5
 pytest-cov
 happybase>=1.0.0
+-r logging.txt
diff --git a/setup.py b/setup.py
@@ -54,6 +54,7 @@
         ],
         'logging': [
             'colorlog>=2.4.0',
+            'python-json-logger>=0.1.5'
         ],
         'tldextract': [
             'tldextract>=1.5.1',
@@ -80,6 +81,8 @@
         "scrapy>=0.24",
         "tldextract>=1.5.1",
         "SQLAlchemy>=1.0.0",
-        "cachetools"
+        "cachetools",
+        "colorlog>=2.4.0",
+        "python-json-logger>=0.1.5"
     ]
 )
diff --git a/tests/test_formatters.py b/tests/test_formatters.py
@@ -0,0 +1,164 @@
+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 = {
+    'bold_yellow': '\x1b[01;33m',
+    'green': '\x1b[32m',
+    'red': '\x1b[31m',
+    'reset': '\x1b[0m',
+    'white': '\x1b[37m',
+}
+
+
+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']))
diff --git a/tests/utils.py b/tests/utils.py
@@ -0,0 +1,54 @@
+import six
+import logging
+import logging.config
+
+
+DEFAULT_LOGGING = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'formatters': {
+        'message': {
+            'format': '%(message)s'
+        }
+    },
+    'handlers': {
+        'console': {
+            'level': 'DEBUG',
+            'class': 'logging.StreamHandler',
+            'formatter': 'message',
+        }
+    },
+    'loggers': {
+        'frontera': {
+            'handlers': ['console'],
+            'level': 'DEBUG',
+        },
+    }
+}
+
+
+class LoggingCaptureMixin(object):
+    """
+    Capture the output from the 'frontera' logger and store it on the class's
+    logger_output attribute.
+    """
+
+    def setUp(self):
+        self.logger = logging.getLogger('frontera')
+        self.old_stream = self.logger.handlers[0].stream
+        self.logger_output = six.StringIO()
+        self.logger.handlers[0].stream = self.logger_output
+
+    def tearDown(self):
+        self.logger.handlers[0].stream = self.old_stream
+
+
+class SetupDefaultLoggingMixin(object):
+    @classmethod
+    def setUpClass(cls):
+        super(SetupDefaultLoggingMixin, cls).setUpClass()
+        logging.config.dictConfig(DEFAULT_LOGGING)
+
+    @classmethod
+    def tearDownClass(cls):
+        super(SetupDefaultLoggingMixin, cls).tearDownClass()