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

Proposed by Facundo Batista on 2015-08-20
Status: Merged
Approved by: Facundo Batista on 2015-08-21
Approved revision: 22
Merged at revision: 21
Proposed branch: lp:~facundo/uservice-logging/monkeypatch-safe-encoder
Merge into: lp:uservice-logging
Diff against target: 166 lines (+81/-11)
2 files modified
uservice_logging/logging.py (+30/-6)
uservice_logging/tests/test_logging.py (+51/-5)
To merge this branch: bzr merge lp:~facundo/uservice-logging/monkeypatch-safe-encoder
Reviewer Review Type Date Requested Status
Celso Providelo (community) 2015-08-20 Approve on 2015-08-20
Review via email: mp+268619@code.launchpad.net

Commit message

Make logstash to use a safe serializer.

Description of the change

Make logstash to use a safe serializer.

To post a comment you must log in.
22. By Facundo Batista on 2015-08-20

Don't even fail on repr problems.

Celso Providelo (cprov) wrote :

Facundo,

Thanks for accommodating issues with object representation pointed by Samuele.

review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'uservice_logging/logging.py'
2--- uservice_logging/logging.py 2015-08-03 15:15:05 +0000
3+++ uservice_logging/logging.py 2015-08-20 16:48:54 +0000
4@@ -18,6 +18,8 @@
5 """Code to configure logging for micro-services."""
6
7 import collections
8+import datetime
9+import json
10 import logging
11 import logging.handlers
12 import logstash
13@@ -32,6 +34,26 @@
14 _logging_configured = []
15
16
17+class SafeEncoder(json.JSONEncoder):
18+ """A JSON encoder that never fails to encode a field."""
19+ def default(self, obj):
20+ # try to get nice formatting for known types
21+ if isinstance(obj, datetime.datetime):
22+ return obj.isoformat()
23+
24+ # fallback to just get object's repr
25+ try:
26+ return repr(obj)
27+ except:
28+ # but if repr fails, just get its info at 'object' level
29+ return "<<Unrepresentable: {} >>".format(object.__repr__(obj))
30+
31+
32+def safe_serializer(message):
33+ dumped = json.dumps(message, cls=SafeEncoder)
34+ return dumped.encode('utf8')
35+
36+
37 def configure_logging(config, service, **kwds):
38 """Simplified setup for the micro-service logging.
39
40@@ -110,13 +132,15 @@
41 root_logger.addHandler(handler)
42
43 if logstash_config:
44- root_logger.addHandler(
45- logstash.LogstashHandler(
46- logstash_config['host'],
47- int(logstash_config['port']),
48- version=int(logstash_config['version'])
49- )
50+ handler = logstash.LogstashHandler(
51+ logstash_config['host'],
52+ int(logstash_config['port']),
53+ version=int(logstash_config['version'])
54 )
55+ # monkeypatch the serializer in the handler's formatter to
56+ # use the own safe serializer
57+ handler.formatter.serialize = safe_serializer
58+ root_logger.addHandler(handler)
59
60
61 class ExtraLogger(logging.Logger):
62
63=== modified file 'uservice_logging/tests/test_logging.py'
64--- uservice_logging/tests/test_logging.py 2015-08-03 15:15:05 +0000
65+++ uservice_logging/tests/test_logging.py 2015-08-20 16:48:54 +0000
66@@ -17,13 +17,16 @@
67
68 """Tests for the logging code."""
69
70+import datetime
71+import json
72 import logging
73 import os.path
74 import subprocess
75 import sys
76 import tempfile
77+import threading
78+
79 from textwrap import dedent
80-import threading
81
82 from fixtures import Fixture
83 from testtools import TestCase
84@@ -243,7 +246,7 @@
85 def test_extra_args_via_subclass(self):
86 class XLogger(util_logging.ExtraLogger):
87 extra_args = dict(bar='baz')
88- logger, filt = self.create_log_with_filter(__name__+'.x', XLogger)
89+ logger, filt = self.create_log_with_filter(__name__ + '.x', XLogger)
90 self.assertThat(logger, IsInstance(XLogger))
91 logger.info("Testing")
92
93@@ -253,7 +256,7 @@
94 class XLogger(util_logging.ExtraLogger):
95 prefix = 'z.'
96 extra_args = dict(bar='baz')
97- logger, filt = self.create_log_with_filter(__name__+'.x.z', XLogger)
98+ logger, filt = self.create_log_with_filter(__name__ + '.x.z', XLogger)
99 logger.info("Testing", extra=dict(a='bar'))
100
101 self.assertThat(filt.log_records[0].bar, Equals('baz'))
102@@ -277,7 +280,7 @@
103 def test_extra_args_additive_and_reset(self):
104 class XLogger(util_logging.ExtraLogger):
105 extra_args = dict(bar='baz')
106- logger, filt = self.create_log_with_filter(__name__+'.x.add', XLogger)
107+ logger, filt = self.create_log_with_filter(__name__ + '.x.add', XLogger)
108 logger.add_extra_args(dict(foo='bar'))
109 logger.info("Testing")
110
111@@ -293,7 +296,7 @@
112 def test_extra_args_thread_safe(self):
113 class XLogger(util_logging.ExtraLogger):
114 extra_args = dict(bar='baz')
115- logger, filt = self.create_log_with_filter(__name__+'.x.safe', XLogger)
116+ logger, filt = self.create_log_with_filter(__name__ + '.x.safe', XLogger)
117 logger.add_extra_args(dict(foo='from1'))
118
119 def t2():
120@@ -308,3 +311,46 @@
121 self.assertThat(filt.log_records[0].foo, Equals('from2'))
122 self.assertThat(filt.log_records[1].bar, Equals('baz'))
123 self.assertThat(filt.log_records[1].foo, Equals('from1'))
124+
125+
126+class SafeEncodingTests(TestCase):
127+ """Test the safe encoder.
128+
129+ Always decode to check equality so order is not a problem.
130+ """
131+
132+ def test_simple(self):
133+ raw = util_logging.safe_serializer(dict(foo='bar'))
134+ resp = json.loads(raw.decode('utf8'))
135+ self.assertEqual(resp, {"foo": "bar"})
136+
137+ def test_datetime_simple(self):
138+ dt = datetime.datetime(2015, 8, 20)
139+ raw = util_logging.safe_serializer(dict(foo='bar', date=dt))
140+ resp = json.loads(raw.decode('utf8'))
141+ self.assertEqual(resp, {"foo": "bar", "date": "2015-08-20T00:00:00"})
142+
143+ def test_datetime_deep(self):
144+ dt = datetime.datetime(2015, 8, 20)
145+ raw = util_logging.safe_serializer(dict(foo='bar', info=dict(date=dt)))
146+ resp = json.loads(raw.decode('utf8'))
147+ self.assertEqual(resp, {"foo": "bar", "info": {"date": "2015-08-20T00:00:00"}})
148+
149+ def test_whatever_object(self):
150+ class Whatever(object):
151+ def __repr__(self):
152+ return 'test repr'
153+
154+ raw = util_logging.safe_serializer(dict(foo='bar', obj=Whatever()))
155+ resp = json.loads(raw.decode('utf8'))
156+ self.assertEqual(resp, {"foo": "bar", "obj": "test repr"})
157+
158+ def test_crashing_repr(self):
159+ class Whatever(object):
160+ def __repr__(self):
161+ return ValueError("pumba")
162+
163+ raw = util_logging.safe_serializer(dict(foo='bar', obj=Whatever()))
164+ unrep_msg = json.loads(raw.decode('utf8'))['obj']
165+ self.assertIn("Unrepresentable", unrep_msg)
166+ self.assertIn("Whatever", unrep_msg)

Subscribers

People subscribed via source and target branches