add python logger backend

Change-Id: I524111d77e1c13bd70aa75088f199c6e294489db

eventtracking/backends/logger.py

+"""Event tracker backend that saves events to a python logger."""
+
+from __future__ import absolute_import
+
+from datetime import datetime
+from datetime import date
+import logging
+import json
+
+from pytz import UTC
+
+MAX_EVENT_SIZE = 1024  # 1 KB
+
+
+class LoggerBackend(object):
+    """
+    Event tracker backend that uses a python logger.
+
+    Events are logged to the INFO level as JSON strings.
+    """
+
+    def __init__(self, **kwargs):
+        """
+        Event tracker backend that uses a python logger.
+
+        `name` is an identifier for the logger, which should have
+            been configured using the default python mechanisms.
+        """
+        name = kwargs.get('name', None)
+        self.max_event_size = kwargs.get('max_event_size', MAX_EVENT_SIZE)
+        self.event_logger = logging.getLogger(name)
+        level = kwargs.get('level', 'info')
+        self.log = getattr(self.event_logger, level.lower())
+
+    def send(self, event):
+        """Send the event to the standard python logger"""
+        event_str = json.dumps(event, cls=DateTimeJSONEncoder)
+
+        # TODO: do something smarter than simply dropping the event on
+        # the floor.
+        if self.max_event_size is None or len(event_str) <= self.max_event_size:
+            self.log(event_str)
+
+
+class DateTimeJSONEncoder(json.JSONEncoder):
+    """JSON encoder aware of datetime.datetime and datetime.date objects"""
+
+    def default(self, obj):  # pylint: disable=method-hidden
+        """
+        Serialize datetime and date objects of iso format.
+
+        datatime objects are converted to UTC.
+        """
+
+        if isinstance(obj, datetime):
+            if obj.tzinfo is None:
+                # Localize to UTC naive datetime objects
+                obj = UTC.localize(obj)  # pylint: disable=no-value-for-parameter
+            else:
+                # Convert to UTC datetime objects from other timezones
+                obj = obj.astimezone(UTC)
+            return obj.isoformat()
+        elif isinstance(obj, date):
+            return obj.isoformat()
+
+        return super(DateTimeJSONEncoder, self).default(obj)

eventtracking/backends/tests/test_logger.py

+"""Test the logging backend"""
+
+from __future__ import absolute_import
+
+import json
+import datetime
+import pytz
+
+from unittest import TestCase
+from mock import patch
+from mock import sentinel
+
+from eventtracking.backends.logger import LoggerBackend
+
+
+class TestLoggerBackend(TestCase):
+    """Test the logging backend"""
+
+    def setUp(self):
+        patcher = patch('eventtracking.backends.logger.logging')
+        self.mock_logging = patcher.start()
+        self.addCleanup(patcher.stop)
+        self.mock_logger = self.mock_logging.getLogger.return_value
+
+        # This will call the mocks
+        self.backend = LoggerBackend()
+
+        # Reset them so that we get "clean" mocks in our tests
+        self.mock_logging.reset_mock()
+        self.mock_logger.reset_mock()
+
+    def test_logs_to_correct_named_logger(self):
+        backend = LoggerBackend(name=sentinel.logger_name)
+        self.mock_logging.getLogger.assert_called_once_with(sentinel.logger_name)
+        backend.send({})
+        self.assert_event_emitted({})
+
+    def assert_event_emitted(self, event):
+        """Asserts exactly one event was emitted"""
+        self.mock_logger.info.assert_called_once_with(
+            json.dumps(event)
+        )
+
+    def test_unserializable_event(self):
+        with self.assertRaises(TypeError):
+            self.backend.send({'foo': object()})
+        self.assert_no_events_emitted()
+
+    def assert_no_events_emitted(self):
+        """Asserts no events have been emitted"""
+        self.assertFalse(self.mock_logger.info.called)
+
+    def test_big_event(self):
+        backend = LoggerBackend(max_event_size=10)
+        backend.send({'foo': 'a'*(backend.max_event_size + 1)})
+        self.assert_no_events_emitted()
+
+    def test_unlimited_event_size(self):
+        default_max_event_size = self.backend.max_event_size
+        backend = LoggerBackend(max_event_size=None)
+        event = {'foo': 'a'*(default_max_event_size + 1)}
+        backend.send(event)
+        self.assert_event_emitted(event)
+
+    def test_event_with_datetime_fields(self):
+        eastern_tz = pytz.timezone('US/Eastern')
+        test_time = datetime.datetime(2012, 05, 01, 07, 27, 01, 200)
+        event = {
+            'test': True,
+            'time': test_time,
+            'converted_time': eastern_tz.localize(test_time),
+            'date': datetime.date(2012, 05, 07)
+        }
+
+        self.backend.send(event)
+        self.assert_event_emitted({
+            'test': True,
+            'time': '2012-05-01T07:27:01.000200+00:00',
+            'converted_time': '2012-05-01T11:27:01.000200+00:00',
+            'date': '2012-05-07'
+        })
+
+    def test_multiple_events(self):
+        for event in [{'a': 'a'}, {'b': 'b'}]:
+            self.backend.send(event)
+            self.assert_event_emitted(event)
+            self.mock_logger.info.reset_mock()
+
+    def test_dynamic_level(self):
+        backend = LoggerBackend(level='warning')
+        backend.send({})
+        self.assertFalse(self.mock_logger.info.called)
+        self.mock_logger.warning.assert_called_once_with('{}')

eventtracking/backends/tests/test_logger_integration.py

+"""
+Runs invasive tests to ensure that the tracking system can communicate with
+the actual python logging system.
+"""
+
+from __future__ import absolute_import
+
+from datetime import datetime
+import json
+import logging
+import os
+import tempfile
+
+from pytz import UTC
+
+from eventtracking.backends.tests import IntegrationTestCase
+from eventtracking.backends.tests import InMemoryBackend
+from eventtracking.backends.logger import LoggerBackend
+from eventtracking.tracker import Tracker
+
+
+class TestLoggerIntegration(IntegrationTestCase):
+    """
+    Writes a real log file and ensures the messages are written properly.
+    """
+
+    def setUp(self):
+
+        logger_name = 'integration.test'
+        test_logger = logging.getLogger(logger_name)
+        test_logger.setLevel(logging.INFO)
+
+        self.temporary_fd, self.temporary_file_name = tempfile.mkstemp()
+        self.addCleanup(os.remove, self.temporary_file_name)
+
+        self.temporary_file_handler = logging.FileHandler(self.temporary_file_name, mode='w', encoding='utf_8')
+        self.temporary_file_handler.setFormatter(logging.Formatter(fmt='%(message)s'))
+        test_logger.addHandler(self.temporary_file_handler)
+        self.addCleanup(test_logger.removeHandler, self.temporary_file_handler)
+
+        self.logger_backend = LoggerBackend(name=logger_name)
+        self.memory_backend = InMemoryBackend()
+        self.tracker = Tracker({
+            'logger': self.logger_backend,
+            'mem': self.memory_backend
+        })
+
+    def test_sequential_events(self):
+        now = datetime.now(UTC)
+        for i in range(10):
+            self.tracker.emit('org.test.logger.integration', {
+                'email': 'tester@eventtracking.org',
+                'sequence': i,
+                'current_time': now
+            })
+
+        # The custom JSON encoder will string encode these fields, however
+        # it is not used to decode the events, so we need to compare these
+        # fields as strings.
+        for event in self.memory_backend.events:
+            event['timestamp'] = event['timestamp'].isoformat()
+            event['data']['current_time'] = event['data']['current_time'].isoformat()
+        self.assertEquals(len(self.memory_backend.events), 10)
+
+        written_events = []
+        with os.fdopen(self.temporary_fd, 'r') as temporary_file:
+            for line in temporary_file:
+                loaded_event = json.loads(line.strip())
+                written_events.append(loaded_event)
+
+        self.assertEquals(written_events, self.memory_backend.events)