Merge lp:~facundo/uservice-logging/monkeypatch-safe-encoder into lp:uservice-logging

[Facundo Batista]

Make logstash to use a safe serializer.

Make logstash to use a safe serializer.

[lp:~facundo/uservice-logging/monkeypatch-safe-encoder]

22. By Facundo Batista on 2015-08-20

Don't even fail on repr problems.

[Celso Providelo (cprov)]

Facundo,

Thanks for accommodating issues with object representation pointed by Samuele.

review: Approve

=== modified file 'uservice_logging/logging.py'
--- uservice_logging/logging.py	2015-08-03 15:15:05 +0000
+++ uservice_logging/logging.py	2015-08-20 16:48:54 +0000
@@ -18,6 +18,8 @@
 """Code to configure logging for micro-services."""
 
 import collections
+import datetime
+import json
 import logging
 import logging.handlers
 import logstash
@@ -32,6 +34,26 @@
 _logging_configured = []
 
 
+class SafeEncoder(json.JSONEncoder):
+    """A JSON encoder that never fails to encode a field."""
+    def default(self, obj):
+        # try to get nice formatting for known types
+        if isinstance(obj, datetime.datetime):
+            return obj.isoformat()
+
+        # fallback to just get object's repr
+        try:
+            return repr(obj)
+        except:
+            # but if repr fails, just get its info at 'object' level
+            return "<<Unrepresentable: {} >>".format(object.__repr__(obj))
+
+
+def safe_serializer(message):
+    dumped = json.dumps(message, cls=SafeEncoder)
+    return dumped.encode('utf8')
+
+
 def configure_logging(config, service, **kwds):
     """Simplified setup for the micro-service logging.
 
@@ -110,13 +132,15 @@
     root_logger.addHandler(handler)
 
     if logstash_config:
-        root_logger.addHandler(
-            logstash.LogstashHandler(
-                logstash_config['host'],
-                int(logstash_config['port']),
-                version=int(logstash_config['version'])
-            )
+        handler = logstash.LogstashHandler(
+            logstash_config['host'],
+            int(logstash_config['port']),
+            version=int(logstash_config['version'])
         )
+        # monkeypatch the serializer in the handler's formatter to
+        # use the own safe serializer
+        handler.formatter.serialize = safe_serializer
+        root_logger.addHandler(handler)
 
 
 class ExtraLogger(logging.Logger):

=== modified file 'uservice_logging/tests/test_logging.py'
--- uservice_logging/tests/test_logging.py	2015-08-03 15:15:05 +0000
+++ uservice_logging/tests/test_logging.py	2015-08-20 16:48:54 +0000
@@ -17,13 +17,16 @@
 
 """Tests for the logging code."""
 
+import datetime
+import json
 import logging
 import os.path
 import subprocess
 import sys
 import tempfile
+import threading
+
 from textwrap import dedent
-import threading
 
 from fixtures import Fixture
 from testtools import TestCase
@@ -243,7 +246,7 @@
     def test_extra_args_via_subclass(self):
         class XLogger(util_logging.ExtraLogger):
             extra_args = dict(bar='baz')
-        logger, filt = self.create_log_with_filter(__name__+'.x', XLogger)
+        logger, filt = self.create_log_with_filter(__name__ + '.x', XLogger)
         self.assertThat(logger, IsInstance(XLogger))
         logger.info("Testing")
 
@@ -253,7 +256,7 @@
         class XLogger(util_logging.ExtraLogger):
             prefix = 'z.'
             extra_args = dict(bar='baz')
-        logger, filt = self.create_log_with_filter(__name__+'.x.z', XLogger)
+        logger, filt = self.create_log_with_filter(__name__ + '.x.z', XLogger)
         logger.info("Testing", extra=dict(a='bar'))
 
         self.assertThat(filt.log_records[0].bar, Equals('baz'))
@@ -277,7 +280,7 @@
     def test_extra_args_additive_and_reset(self):
         class XLogger(util_logging.ExtraLogger):
             extra_args = dict(bar='baz')
-        logger, filt = self.create_log_with_filter(__name__+'.x.add', XLogger)
+        logger, filt = self.create_log_with_filter(__name__ + '.x.add', XLogger)
         logger.add_extra_args(dict(foo='bar'))
         logger.info("Testing")
 
@@ -293,7 +296,7 @@
     def test_extra_args_thread_safe(self):
         class XLogger(util_logging.ExtraLogger):
             extra_args = dict(bar='baz')
-        logger, filt = self.create_log_with_filter(__name__+'.x.safe', XLogger)
+        logger, filt = self.create_log_with_filter(__name__ + '.x.safe', XLogger)
         logger.add_extra_args(dict(foo='from1'))
 
         def t2():
@@ -308,3 +311,46 @@
         self.assertThat(filt.log_records[0].foo, Equals('from2'))
         self.assertThat(filt.log_records[1].bar, Equals('baz'))
         self.assertThat(filt.log_records[1].foo, Equals('from1'))
+
+
+class SafeEncodingTests(TestCase):
+    """Test the safe encoder.
+
+    Always decode to check equality so order is not a problem.
+    """
+
+    def test_simple(self):
+        raw = util_logging.safe_serializer(dict(foo='bar'))
+        resp = json.loads(raw.decode('utf8'))
+        self.assertEqual(resp, {"foo": "bar"})
+
+    def test_datetime_simple(self):
+        dt = datetime.datetime(2015, 8, 20)
+        raw = util_logging.safe_serializer(dict(foo='bar', date=dt))
+        resp = json.loads(raw.decode('utf8'))
+        self.assertEqual(resp, {"foo": "bar", "date": "2015-08-20T00:00:00"})
+
+    def test_datetime_deep(self):
+        dt = datetime.datetime(2015, 8, 20)
+        raw = util_logging.safe_serializer(dict(foo='bar', info=dict(date=dt)))
+        resp = json.loads(raw.decode('utf8'))
+        self.assertEqual(resp, {"foo": "bar", "info": {"date": "2015-08-20T00:00:00"}})
+
+    def test_whatever_object(self):
+        class Whatever(object):
+            def __repr__(self):
+                return 'test repr'
+
+        raw = util_logging.safe_serializer(dict(foo='bar', obj=Whatever()))
+        resp = json.loads(raw.decode('utf8'))
+        self.assertEqual(resp, {"foo": "bar", "obj": "test repr"})
+
+    def test_crashing_repr(self):
+        class Whatever(object):
+            def __repr__(self):
+                return ValueError("pumba")
+
+        raw = util_logging.safe_serializer(dict(foo='bar', obj=Whatever()))
+        unrep_msg = json.loads(raw.decode('utf8'))['obj']
+        self.assertIn("Unrepresentable", unrep_msg)
+        self.assertIn("Whatever", unrep_msg)